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:
None 
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
Description:
It appears that calling a stored proc/func while in another default db is slower than doing a local reference. Since a db.xxx reference is purely a namespace issue and internally it's always resolved to a full db.xxx ref for execution (at least for tablenames in a query), there should be no speed difference here either.

This info comes from http://forums.mysql.com/read.php?24,200278,206145
(the test case/verification below comes from me)

How to repeat:
mysql> create function foo (i int) returns int return 0;

mysql> select benchmark(100000,foo(0));
+--------------------------+
| benchmark(100000,foo(0)) |
+--------------------------+
|                        0 | 
+--------------------------+
1 row in set (0.23 sec)

(consistently stays at 0.23 sec when run multiple times)

mysql> use mysql
mysql> select benchmark(100000,test.foo(0));
+-------------------------------+
| benchmark(100000,test.foo(0)) |
+-------------------------------+
|                             0 | 
+-------------------------------+
1 row in set (2.25 sec)

(again, consistenly stays at this duration for any number of runs)

mysql> use information_schema
mysql> select benchmark(100000,test.foo(0));
+-------------------------------+
| benchmark(100000,test.foo(0)) |
+-------------------------------+
|                             0 | 
+-------------------------------+
1 row in set (1.45 sec)

(different from myqsl, but stays consistent when run repeatedly)

mysql> use test
mysql> select benchmark(100000,test.foo(0));
+-------------------------------+
| benchmark(100000,test.foo(0)) |
+-------------------------------+
|                             0 | 
+-------------------------------+
1 row in set (0.23 sec)

(just to be sure that merely specifying the db. reference does not change things)

Suggested fix:
Fix whatever is causing this slow down, as it is probably unnecessary.
[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