[MDEV-5541] every subsequent DROP TABLE is slower Created: 2014-01-18  Updated: 2014-02-27  Resolved: 2014-02-27

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.0.7
Fix Version/s: 10.0.8

Type: Bug Priority: Major
Reporter: Pawel Pabian (Inactive) Assignee: Unassigned
Resolution: Fixed Votes: 1
Labels: upstream
Environment:

Debian GNU/Linux 7: 3.2.38-vs2.3.2.16-beng #1 SMP Tue Feb 12 10:48:52 GMT 2013 x86_64 GNU/Linux

Default config with increased innodb buffer size to 20GB and file per table turned on.


 Description   

Each test CREATEs and DROPs 1024 tables. I've checked that CREATE time is constant, while DROP time increases every time it is invoked.

while true; do time perl -e 'print "CREATE TABLE foo (id int) Engine=InnoDB; DROP TABLE foo;\n" for 1..1024' | mysql test; done
 
 
 
real	0m2.351s
 
user	0m0.020s
 
sys	0m0.040s
 
 
 
real	0m2.340s
 
user	0m0.010s
 
sys	0m0.060s
 
 
 
real	0m2.458s
 
user	0m0.030s
 
sys	0m0.050s
 
 
 
real	0m2.657s
 
user	0m0.030s
 
sys	0m0.040s
 
 
 
real	0m2.914s
 
user	0m0.020s
 
sys	0m0.040s
 
 
 
real	0m3.262s
 
user	0m0.020s
 
sys	0m0.050s
 
 
 
real	0m3.702s
 
user	0m0.020s
 
sys	0m0.040s
 
 
 
real	0m4.187s
 
user	0m0.030s
 
sys	0m0.040s
 
 
 
real	0m4.552s
 
user	0m0.040s
 
sys	0m0.030s
 
 
 
real	0m4.966s
 
user	0m0.020s
 
sys	0m0.050s
 
 
 
real	0m5.327s
 
user	0m0.050s
 
sys	0m0.030s
 
 
 
real	0m5.669s
 
user	0m0.000s
 
sys	0m0.080s
 
 
 
real	0m6.017s
 
user	0m0.010s
 
sys	0m0.070s
 
 
 
real	0m6.322s
 
user	0m0.030s
 
sys	0m0.050s
 
 
 
real	0m6.659s
 
user	0m0.020s
 
sys	0m0.070s
 
 
 
real	0m6.872s
 
user	0m0.020s
 
sys	0m0.050s

DROP time becomes stable when database instance is using maximum allowed amount of RAM. In my case test time can raise from 2.3 second to over 1 minute.

I've checked MariaDB 5.5.34 and PerconaDB 5.6 and they are not affected by this issue - DROP time is constant despite of amount of used RAM.

 Comments   
Comment by Sergei Golubchik [ 2014-01-20 ]

elenst, could you please check whether it's because of the new InnoDB or, may be, because of the table cache changes? Like, try in 10.0 with InnoDB and with XtraDB. And try in older 10.0 before table cache optimizations.

Comment by Elena Stepanova [ 2014-01-31 ]

Hi Pawel,

Do I interpret your output correctly, that it took between 2 seconds to create and drop 1024 tables at first, and then the value was growing gradually? Or did you change the number of tables created per test in the command line comparing to the one used to collect the results?
Could you please attach your cnf file?

I'm asking because it generally takes me many times longer to create InnoDB tables (even on SSD), so I have a difficulty reproducing, the dynamics is very different.

Comment by Pawel Pabian (Inactive) [ 2014-01-31 ]

> Do I interpret your output correctly, that it took between 2 seconds to create and drop 1024 tables at first, and then the value was growing gradually?

Yes. Single test does DROP and CREATE the same table 1024 times. Amount of operations is the same for every test. Each test starts and ends with empty database. Time of every following test is longer.

> Could you please attach your cnf file?

We do not have it anymore. But we reproduced this issue with default config which had only innodb buffer size increased to 20GB and file per table turned on. Generally speaking - the bigger innodb buffer is the worse DROP time you will finally reach.

> I'm asking because it generally takes me many times longer to create InnoDB tables (even on SSD).

Test server has several SSDs in RAID, typical desktop won't even get close to this I/O performance. That's why each test packs 1024 CREATE-DROP actions to make time increase visible. Try to set innodb buffer to maximum amount of RAM you have and decrease amount of actions in each test. You should observe significant DROP time increase between cold database and the moment when it takes all available RAM.

Comment by Elena Stepanova [ 2014-02-27 ]

So far all my attempts to reproduce the problem failed.

  • installed the release 10.0.7 packages from deb repository (which I assume you are using) on Wheezy x86_64, to get the exact same default config;
  • set buffer pool to 8 Gb which was the highest I could do;
  • made sure file-per-table is ON (it is actually in the config already);
  • reduced the number of tables to make the test more dynamic on my non-SSD-RAID machine;
  • ran the test for hours.
    I still didn't get any visible time growth between the runs.
    So, I suppose there is something else to it, apart from the code, build and config.

The next thing to check is whether 20 Gb of buffer pool makes the critical difference. I'm going to acquire one of benchmarking machines with decent amount of memory to see if I can reproduce it there.

Comment by Elena Stepanova [ 2014-02-27 ]

I ran the test with 40 Gb of buffer pool with a single disk and could not get the described trend; but when I switched to a raid, I finally observed it. It's not as monotonic as in Pawel's description, but still undoubtedly growing:

MariaDB [(none)]> select @@innodb_buffer_pool_size, @@innodb_file_per_table, @@version;
 
+---------------------------+-------------------------+--------------------+
 
| @@innodb_buffer_pool_size | @@innodb_file_per_table | @@version          |
 
+---------------------------+-------------------------+--------------------+
 
|               42949672960 |                       1 | 10.0.7-MariaDB-log |
 
+---------------------------+-------------------------+--------------------+
 
1 row in set (0.00 sec)

Single disk (had to reduce the number of threads per step to 64 to make the duration acceptable:

real	0m16.266s
 
user	0m0.008s
 
sys	0m0.004s
 
 
 
real	0m16.358s
 
user	0m0.008s
 
sys	0m0.008s
 
 
 
real	0m21.776s
 
user	0m0.000s
 
sys	0m0.008s
 
 
 
real	0m20.991s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m21.057s
 
user	0m0.004s
 
sys	0m0.004s
 
 
 
real	0m20.110s
 
user	0m0.000s
 
sys	0m0.008s
 
 
 
real	0m20.984s
 
user	0m0.004s
 
sys	0m0.008s
 
 
 
real	0m21.123s
 
user	0m0.008s
 
sys	0m0.004s
 
 
 
real	0m20.044s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m21.609s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m20.733s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m19.460s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m19.989s
 
user	0m0.012s
 
sys	0m0.000s
 
 
 
real	0m20.632s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m20.594s
 
user	0m0.000s
 
sys	0m0.016s
 
 
 
real	0m20.929s
 
user	0m0.000s
 
sys	0m0.008s
 
 
 
real	0m21.351s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m22.042s
 
user	0m0.004s
 
sys	0m0.004s
 
 
 
real	0m19.857s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m20.842s
 
user	0m0.000s
 
sys	0m0.016s
 
 
 
real	0m21.328s
 
user	0m0.000s
 
sys	0m0.008s
 
 
 
real	0m21.250s
 
user	0m0.012s
 
sys	0m0.000s
 
 
 
real	0m21.735s
 
user	0m0.004s
 
sys	0m0.008s
 
 
 
real	0m21.219s
 
user	0m0.004s
 
sys	0m0.008s
 
 
 
real	0m20.284s
 
user	0m0.004s
 
sys	0m0.004s
 
 
 
real	0m20.410s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m22.342s
 
user	0m0.000s
 
sys	0m0.008s
 
 
 
real	0m18.935s
 
user	0m0.004s
 
sys	0m0.004s
 
 
 
real	0m19.715s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m20.947s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m22.217s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m20.248s
 
user	0m0.012s
 
sys	0m0.000s
 
 
 
real	0m20.498s
 
user	0m0.008s
 
sys	0m0.004s
 
 
 
real	0m21.124s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m20.855s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m21.280s
 
user	0m0.004s
 
sys	0m0.004s
 
 
 
real	0m21.064s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m21.580s
 
user	0m0.004s
 
sys	0m0.004s
 
 
 
real	0m21.045s
 
user	0m0.000s
 
sys	0m0.008s
 
 
 
real	0m22.437s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m20.818s
 
user	0m0.000s
 
sys	0m0.008s
 
 
 
real	0m21.363s
 
user	0m0.000s
 
sys	0m0.008s
 
 
 
real	0m19.788s
 
user	0m0.004s
 
sys	0m0.008s
 
 
 
real	0m21.478s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m21.405s
 
user	0m0.008s
 
sys	0m0.000s
 
 
 
real	0m22.389s
 
user	0m0.000s
 
sys	0m0.008s
 
 
 
real	0m21.087s
 
user	0m0.008s
 
sys	0m0.004s
 
 
 
real	0m20.925s
 
user	0m0.004s
 
sys	0m0.012s
 
 
 
real	0m21.346s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m21.131s
 
user	0m0.008s
 
sys	0m0.004s
 
 
 
real	0m22.259s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m20.104s
 
user	0m0.004s
 
sys	0m0.008s
 
 
 
real	0m20.139s
 
user	0m0.004s
 
sys	0m0.008s
 
 
 
real	0m19.996s
 
user	0m0.012s
 
sys	0m0.004s
 
 
 
real	0m19.845s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m22.450s
 
user	0m0.012s
 
sys	0m0.000s
 
 
 
real	0m20.469s
 
user	0m0.000s
 
sys	0m0.008s
 
 
 
real	0m21.695s
 
user	0m0.004s
 
sys	0m0.004s
 
 
 
real	0m20.344s
 
user	0m0.004s
 
sys	0m0.012s
 
 
 
real	0m21.389s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m21.628s
 
user	0m0.000s
 
sys	0m0.012s
 
 
 
real	0m21.183s
 
user	0m0.000s
 
sys	0m0.008s

With raid (returned to original 1024 tables per step):

real	0m2.801s
 
user	0m0.000s
 
sys	0m0.048s
 
 
 
real	0m3.806s
 
user	0m0.128s
 
sys	0m0.024s
 
 
 
real	0m2.880s
 
user	0m0.000s
 
sys	0m0.060s
 
 
 
real	0m4.040s
 
user	0m0.052s
 
sys	0m0.108s
 
 
 
real	0m3.173s
 
user	0m0.024s
 
sys	0m0.040s
 
 
 
real	0m4.466s
 
user	0m0.056s
 
sys	0m0.096s
 
 
 
real	0m3.734s
 
user	0m0.028s
 
sys	0m0.064s
 
 
 
real	0m6.014s
 
user	0m0.104s
 
sys	0m0.068s
 
 
 
real	0m4.866s
 
user	0m0.044s
 
sys	0m0.100s
 
 
 
real	0m8.620s
 
user	0m0.108s
 
sys	0m0.072s
 
 
 
real	0m6.300s
 
user	0m0.080s
 
sys	0m0.112s
 
 
 
real	0m11.630s
 
user	0m0.080s
 
sys	0m0.100s
 
 
 
real	0m7.813s
 
user	0m0.108s
 
sys	0m0.100s
 
 
 
real	0m14.523s
 
user	0m0.060s
 
sys	0m0.128s
 
 
 
real	0m9.092s
 
user	0m0.088s
 
sys	0m0.108s
 
 
 
real	0m17.030s
 
user	0m0.076s
 
sys	0m0.124s
 
 
 
real	0m9.830s
 
user	0m0.104s
 
sys	0m0.104s
 
 
 
real	0m19.210s
 
user	0m0.140s
 
sys	0m0.068s
 
 
 
real	0m18.820s
 
user	0m0.076s
 
sys	0m0.120s
 
 
 
real	0m20.335s
 
user	0m0.096s
 
sys	0m0.104s
 
 
 
real	0m21.628s
 
user	0m0.060s
 
sys	0m0.120s
 
 
 
real	0m22.007s
 
user	0m0.100s
 
sys	0m0.104s
 
 
 
real	0m23.429s
 
user	0m0.076s
 
sys	0m0.116s
 
 
 
real	0m23.655s
 
user	0m0.096s
 
sys	0m0.112s
 
 
 
real	0m25.043s
 
user	0m0.052s
 
sys	0m0.136s
 
 
 
real	0m25.193s
 
user	0m0.104s
 
sys	0m0.120s
 
 
 
real	0m26.684s
 
user	0m0.096s
 
sys	0m0.100s

Now when it became reproducible, I should be able to find out the source as serg requested.

Comment by Elena Stepanova [ 2014-02-27 ]

The bug existed in InnoDB of 5.6.10, reproducible on MySQL 5.6.10. It was fixed in 10.0.8 release by the merge of InnoDB 5.6.14, in the following revision:

    revno: 3965.1.13
 
    revision-id: sergii@pisem.net-20140201083326-wlzdm7dash8h58m8
 
    parent: sergii@pisem.net-20140201083259-p6b7jmxguoxucnyu
 
    fixes bug: https://mariadb.atlassian.net/browse/MDEV-5574
 
    committer: Sergei Golubchik <sergii@pisem.net>
 
    branch nick: 10.0
 
    timestamp: Sat 2014-02-01 09:33:26 +0100
 
    message:
 
      MDEV-5574 Set AUTO_INCREMENT below max value of column.
 
      Update InnoDB to 5.6.14
 
      Apply MySQL-5.6 hack for MySQL Bug#16434374
 
      Move Aria-only HA_RTREE_INDEX from my_base.h to maria_def.h (breaks an assert in InnoDB)
 
      Fix InnoDB memory leak

Generated at Thu Feb 08 07:05:09 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.