Bug #36229 | Execution overhead of stored function/procedure differs with cross-database call | ||
---|---|---|---|
Submitted: | 21 Apr 2008 13:35 | Modified: | 22 Apr 2008 19:06 |
Reporter: | Arjen Lentz | Email Updates: | |
Status: | Verified | Impact on me: | |
Category: | MySQL Server: Stored Routines | Severity: | S5 (Performance) |
Version: | 5.0.51a, 5.1.24 | OS: | Any |
Assigned to: | CPU Architecture: | Any | |
Tags: | Stored Functions, stored procedures |
[21 Apr 2008 13:35]
Arjen Lentz
[21 Apr 2008 14:24]
Peter Laursen
for me it is even worse! mysql> use test Database changed mysql> create function foo (i int) returns int return 0; Query OK, 0 rows affected (0.19 sec) mysql> use test; Database changed mysql> select benchmark(100000,foo(0)); +--------------------------+ | benchmark(100000,foo(0)) | +--------------------------+ | 0 | +--------------------------+ 1 row in set (0.41 sec) mysql> use mysql; Database changed mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (12.71 sec) mysql> use information_schema; Database changed mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (6.67 sec) mysql> use test; Database changed mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (0.30 sec) mysql> .. also note that first execution and last execution (same DB context - `test`) do not return the same! All execution times here are consistently reproducable. Somewhat a difference between 0.3 seconds and 12.71 seconds! And using another user database as context: mysql> use test4; Database changed mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (10.47 sec) mysql>
[21 Apr 2008 14:31]
Peter Laursen
And 5.1.24 is even worse (my first post was 5.0.51a). Executed on a AMD 2*1.8 64 bit Ghz PC running Vista 64 bit. PC was practically idle ... mysql> use test; Database changed mysql> select benchmark(100000,foo(0)); +--------------------------+ | benchmark(100000,foo(0)) | +--------------------------+ | 0 | +--------------------------+ 1 row in set (0.47 sec) mysql> use mysql; Database changed mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (28.98 sec) mysql> use information_schema; Database changed mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (15.06 sec) mysql> use test; Database changed mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (0.45 sec) mysql> use test2 Database changed mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (26.37 sec) mysql> select version(); +---------------------+ | version() | +---------------------+ | 5.1.24-rc-community | +---------------------+ 1 row in set (0.05 sec) mysql>
[21 Apr 2008 14:34]
Peter Laursen
And very kind of Arjen to assign a 'S5' category for this. This is not marginals! Should be S2 in my opinion!
[21 Apr 2008 14:55]
Davi Arnaut
The overhead is probably due to the fact that each time the stored procedure is called it changes the current database to that of the stored procedure and back at the end. Introduced in patch for Bug#25843.
[21 Apr 2008 15:03]
Peter Laursen
And so it takes up to 26 seconds to change the database context twice? FYI all user databases in my example are almost empty (with a few small silly test&learning tables in them) I doubt this is the complete explanation!
[21 Apr 2008 15:10]
Arjen Lentz
There could be such a context switch at work, but it won't have been introduced with a fix to the other bug. The other issue was fixed only in the 5.1 tree, so 5.0 would still have the original behaviour. Anyway, I don't believe a default db switch causes that much overhead, it's pretty much just a variable in the thread/connection-local space so that the parser can resolve to default when an identifier without specific db is used in a query. Afaik the server doesn't need to do any legwork to change the default db. I do also find it intriguing that the time is constant when run multiple times with the same db, yet different for different dbs.
[21 Apr 2008 15:10]
Davi Arnaut
Peter, it's twice for each time the you call the stored procedure, which in the benchmark case is 100000*2 times. It might not be the complete explanation, but from quick look at the source code that is the first blatant difference when calling a stored procedure from a different database. Also not that the change database is "smart", if you call test.foo() from the test database it does not change the current database.
[21 Apr 2008 15:13]
Peter Laursen
Ok .. got the point. That bugfix may explain the difference between 5.0 and 5.1 then!
[21 Apr 2008 15:21]
Davi Arnaut
Mea culpa: changing the current db was introduced before the aforementioned bug, looking more carefully at the history the database change it was introduced in 5.0 way before Bug#25843.
[21 Apr 2008 16:02]
Davi Arnaut
Arjen, changing the database is not just setting variables -- currently it involves going to the disk to check the existence of the database directory and I think this is the significant overhead in this "benchmark".
[21 Apr 2008 19:45]
Peter Laursen
let us try a function that 'does something' like: =================================================== DELIMITER $$ CREATE FUNCTION `test`.`dbusetest`() RETURNS integer BEGIN declare i int; set i = 0; while i < 100000 do set i = i + 1; end while; return i; END$$ DELIMITER ; ============================================================================================= MySQL 5.0.51a: Enter password: ******** Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 30 Server version: 5.0.51a-community-nt MySQL Community Edition (GPL) Type 'help;' or '\h' for help. Type '\c' to clear the buffer. mysql> use test; Database changed mysql> select test.dbusetest(); +------------------+ | test.dbusetest() | +------------------+ | 100000 | +------------------+ 1 row in set (0.39 sec) mysql> use mysql; Database changed mysql> select test.dbusetest(); +------------------+ | test.dbusetest() | +------------------+ | 100000 | +------------------+ 1 row in set (0.33 sec) mysql> use information_schema; Database changed mysql> select test.dbusetest(); +------------------+ | test.dbusetest() | +------------------+ | 100000 | +------------------+ 1 row in set (0.33 sec) mysql> use test4; Database changed mysql> select test.dbusetest(); +------------------+ | test.dbusetest() | +------------------+ | 100000 | +------------------+ 1 row in set (0.33 sec) mysql> use test; Database changed mysql> select benchmark(50,test.dbusetest()); +--------------------------------+ | benchmark(50,test.dbusetest()) | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (16.40 sec) mysql> use mysql; Database changed mysql> select benchmark(50,test.dbusetest()); +--------------------------------+ | benchmark(50,test.dbusetest()) | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (16.52 sec) mysql> use information_schema; Database changed mysql> select benchmark(50,test.dbusetest()); +--------------------------------+ | benchmark(50,test.dbusetest()) | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (16.46 sec) mysql> use test; Database changed mysql> select benchmark(50,test.dbusetest()); +--------------------------------+ | benchmark(50,test.dbusetest()) | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (16.36 sec) mysql> use test4; Database changed mysql> select benchmark(50,test.dbusetest()); +--------------------------------+ | benchmark(50,test.dbusetest()) | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (16.46 sec) mysql> ============================================================================================= MySQL 5.1.24: Enter password: ******** Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 13 Server version: 5.1.24-rc-community MySQL Community Server (GPL) Type 'help;' or '\h' for help. Type '\c' to clear the buffer. mysql> use test; Database changed mysql> select test.dbusetest(); +------------------+ | test.dbusetest() | +------------------+ | 100000 | +------------------+ 1 row in set (0.42 sec) mysql> use mysql; Database changed mysql> select test.dbusetest(); +------------------+ | test.dbusetest() | +------------------+ | 100000 | +------------------+ 1 row in set (0.33 sec) mysql> use information_schema; Database changed mysql> select test.dbusetest(); +------------------+ | test.dbusetest() | +------------------+ | 100000 | +------------------+ 1 row in set (0.33 sec) mysql> use test2; Database changed mysql> select test.dbusetest(); +------------------+ | test.dbusetest() | +------------------+ | 100000 | +------------------+ 1 row in set (0.33 sec) mysql> use test; Database changed mysql> select benchmark(50,test.dbusetest()); +--------------------------------+ | benchmark(50,test.dbusetest()) | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (16.80 sec) mysql> use mysql; Database changed mysql> select benchmark(50,test.dbusetest()); +--------------------------------+ | benchmark(50,test.dbusetest()) | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (16.67 sec) mysql> use information_schema; Database changed mysql> select benchmark(50,test.dbusetest()); +--------------------------------+ | benchmark(50,test.dbusetest()) | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (16.76 sec) mysql> use test; Database changed mysql> select benchmark(50,test.dbusetest()); +--------------------------------+ | benchmark(50,test.dbusetest()) | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (16.72 sec) mysql> use test2; Database changed mysql> select benchmark(50,test.dbusetest()); +--------------------------------+ | benchmark(50,test.dbusetest()) | +--------------------------------+ | 0 | +--------------------------------+ 1 row in set (16.72 sec) mysql>
[21 Apr 2008 19:55]
Peter Laursen
Now it is not very significant in above example. Anyway *something* happened between 5.0 and 5.1. That is visible also with 50 recursions. Wiht lots of small functions (and recursive functions in particular) it may still be important to USE the best database context. It should at least be documented like that. I guess nobody realized that it would really matter. I think exactly the same would apply to 'ordinary' statements (like SELECT, UPDATE etc.)? This may be somewhat a problem with GUI clients as the GUI interface will send "USE I_S" followed by "SELECT .." to get information to populate the GUI interface independently of what statements user executes from an editor interface of such client. If USE statements should be avoided by a client for performance reasons except in context with DML statements if should *definitely* be documented like that!
[21 Apr 2008 20:17]
Peter Laursen
btw: why will the server need to access disk to verify the existence of Information_Schema .... that does not hold water! :-)
[21 Apr 2008 22:41]
Davi Arnaut
There is no access to disk when switching to the IS database, but it still switches to the database of the stored procedure. The access check is the only thing that guarantees that the database exists and I guess the access check is because you can move a database of myisam tables and work on even without restarting the server at all. We could improve this if it's really important by caching the filesystem responses or something like.
[22 Apr 2008 19:06]
Valeriy Kravchuk
On my laptop difference is the following: C:\Program Files\MySQL\MySQL Server 5.1\bin>mysql -uroot test -P3310 Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 9 Server version: 5.1.24-rc-community MySQL Community Server (GPL) Type 'help;' or '\h' for help. Type '\c' to clear the buffer. mysql> create function foo (i int) returns int return 0; Query OK, 0 rows affected (0.24 sec) mysql> select benchmark(100000,foo(0)); +--------------------------+ | benchmark(100000,foo(0)) | +--------------------------+ | 0 | +--------------------------+ 1 row in set (0.48 sec) mysql> select benchmark(100000,foo(0)); +--------------------------+ | benchmark(100000,foo(0)) | +--------------------------+ | 0 | +--------------------------+ 1 row in set (0.44 sec) mysql> select benchmark(100000,foo(0)); +--------------------------+ | benchmark(100000,foo(0)) | +--------------------------+ | 0 | +--------------------------+ 1 row in set (0.42 sec) mysql> use mysql Database changed mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (10.47 sec) mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (10.44 sec) mysql> select benchmark(100000,test.foo(0)); +-------------------------------+ | benchmark(100000,test.foo(0)) | +-------------------------------+ | 0 | +-------------------------------+ 1 row in set (10.48 sec) So, more thatn 20 times slower.
[23 Apr 2008 5:35]
MySQL Verification Team
anyone tried oprofile or some profiler ?
[23 Apr 2008 10:07]
Davi Arnaut
A oprofile run would interesting, it will probably show of lot of time spent in the access syscall.
[9 Jan 2009 15:29]
Michael Hase
Yes, it is the access() system call. We have exactly the same problem. Stored function in a different database increases runtime of a query from 0.2 sec to 0.4sec. A system call trace shows a massive amount of access calls, we have a full table scan here. Pattern is like this: 1222/11: 1.1266 0.0005 read(842, 0x10BE32090, 290268) = 290268 1222/11: 1.6272 0.5006 access("./db1", F_OK) = 0 1222/11: 1.6277 0.0005 access("./db2", F_OK) = 0 ... 13200 times access(), no other system calls ... 1222/11: 3.1870 0.0001 access("./db2", F_OK) = 0 1222/11: 3.1871 0.0001 access("./db1", F_OK) = 0 1222/11: 3.1872 0.0001 access("./db2", F_OK) = 0 1222/11: 3.1881 0.0009 write(25, 0x118751C20, 314) = 314 It looks like accessibility of the db directories is checked for every record, as we have 6600 records in our table. Couldn't this be checked once at parse time? Cheers, Michael