Beefy Boxes and Bandwidth Generously Provided by pair Networks
Keep It Simple, Stupid
 
PerlMonks  

MySQL Query Time DBI

by KynkoKat (Novice)
on Oct 16, 2008 at 21:06 UTC ( [id://717593]=perlquestion: print w/replies, xml ) Need Help??

KynkoKat has asked for the wisdom of the Perl Monks concerning the following question:

In MySQL when you run a query it will return what you looked for and the count of the number of rows it returned and the time it took to find them.

Example:
mysql> select * from shop; +---------+--------+-------+ | article | dealer | price | +---------+--------+-------+ | 0001 | A | 3.45 | | 0001 | B | 3.99 | | 0002 | A | 10.99 | | 0003 | B | 1.45 | | 0003 | C | 1.69 | | 0003 | D | 1.25 | | 0004 | D | 19.95 | +---------+--------+-------+ 7 rows in set (0.00 sec)
With DBI I can grab all the data from the table itself, but what I'm after is the "7 rows in set (0.00 sec)" part. Well, mainly the "(0.00 sec)" part. Does anyone know how to obtain it? (With or without DBI)

Replies are listed 'Best First'.
Re: MySQL Query Time DBI
by moritz (Cardinal) on Oct 16, 2008 at 21:15 UTC
    Call time before and after the query, and calculate the difference. That will give you a resolution of one second, if that's not enough, load Time::HiRes qw(time) first.
      I believe that the time you see printed is not actually returned by mysqld, but is rather something generated by the mysql command-line interface. What moritz suggested is probably your best bet.
        Illuminatus is correct - the time comes from the mysql command client.

        Not that it helps the OP, but I was interested in finding out about this (and one of the key points of Open Source is that you CAN look at the source!)

        (Based on MySQL 5.0.51a, OpenBSD port)

        client/mysql.cc

        (around line 2049)
        static int com_go(String *buffer,char *line __attribute__((unused))) { char buff[200], time_buff[32], *pos;
        (line 2092)  timer=start_timer();

        (line 2137)      mysql_end_timer(timer,time_buff);

        (line 2170 - the "n rows in set" message)
        sprintf(buff,"%ld %s in set", (long) mysql_num_rows(result), (long) mysql_num_rows(result) == 1 ? "row" : "rows");
        (line 2195)     strmov(pos, time_buff);

        So, what does mysql_end_timer put in time_buff?

        (line 3726, same file, builds the "(" and ")", calling nice_time for the seconds display)
        static void end_timer(ulong start_time,char *buff) { nice_time((double) (start_timer() - start_time) / CLOCKS_PER_SEC,buff,1); } static void mysql_end_timer(ulong start_time,char *buff) { buff[0]=' '; buff[1]='('; end_timer(start_time,buff+2); strmov(strend(buff),")"); }
        (line 3695 - builds the "n sec" part)
        static void nice_time(double sec,char *buff,bool part_second) { ulong tmp; if (sec >= 3600.0*24) { tmp=(ulong) floor(sec/(3600.0*24)); sec-=3600.0*24*tmp; buff=int10_to_str((long) tmp, buff, 10); buff=strmov(buff,tmp > 1 ? " days " : " day "); } if (sec >= 3600.0) { tmp=(ulong) floor(sec/3600.0); sec-=3600.0*tmp; buff=int10_to_str((long) tmp, buff, 10); buff=strmov(buff,tmp > 1 ? " hours " : " hour "); } if (sec >= 60.0) { tmp=(ulong) floor(sec/60.0); sec-=60.0*tmp; buff=int10_to_str((long) tmp, buff, 10); buff=strmov(buff," min "); } if (part_second) sprintf(buff,"%.2f sec",sec); else sprintf(buff,"%d sec",(int) sec); }
        And, so, finally, what does start_timer() do? (line 3684)
        static ulong start_timer(void) { #if defined( __WIN__) || defined( OS2) || defined(__NETWARE__) return clock(); #else struct tms tms_tmp; return times(&tms_tmp); #endif }
        Assuming we are not running on WIN/OS2/NETWARE, we can see what times does:

        http://www.openbsd.org/cgi-bin/man.cgi?query=times&apropos=0&sektion=0&manpath=OpenBSD+Current&arch=i386&format=html

        BUT converting this into Perl is for another day!
Re: MySQL Query Time DBI
by smiffy (Pilgrim) on Oct 17, 2008 at 00:36 UTC

    To get sub-second accuracy, you will need Time::HiRes, as suggested.

    However, please note that you are not going to be showing a particularly accurate sub-second figure as this will not take into account the time it takes for the query to be sent out to the MySQL socket and the result set to be brought back. So, any result will be query time plus 'other overheads'.

    Bear in mind also that the first time that a query is run, it will take longer than if you run it again straight away as the MySQL server may cache the query.

    With all that said, if we were only interested in measuring whole seconds (like running time, as suggested), we can get a greater accuracy by using a stored procedure (MySQL 5.x and greater only.)

    Rather than marking time, sending off the query, receiving the results, marking time, taking the difference, we can do the timing within MySQL itself. Consider the following SQL:

    drop procedure if exists ttest; delimiter // create procedure ttest() BEGIN DECLARE stime int; DECLARE etime int; /* Mark start time. */ select unix_timestamp() into stime; /* Your query goes here. */ show tables; /* Mark end time. */ select unix_timestamp() into etime; /* Calculate time elapsed (integer seconds only.) */ select etime-stime as elapsed_time; END // delimiter ;

    What we are doing is storing the current UNIX time into a variable, running our main query, storing the UNIX time into another variable and then selecting the difference in seconds. The time we are recording is time taken by the MySQL server with no Perl/DBI/socket overhead.

    The query to run this from Perl would be call ttest();. Note that doing this returns 2 result sets, for which your DBI code should be written accordingly. (Here is a node describing this. Google will find you other references.)

    I have to say that the above is probably only of academic interest as I generally find that query times are sub-second (therefore would return elapsed_time=0), even when looking at multi-Gb tables. But it's another way to do it ;-)

    References

    Here is a teaser for the article "MySQL 5.0 New Features: Stored Procedures" by Peter Gulutzan, on the MySQL site. The full article is available as a PDF and is worth reading for anyone starting out with MySQL SP's.

Re: MySQL Query Time DBI
by elmoz (Initiate) on Oct 20, 2008 at 23:39 UTC
    Assuming you want to do this strictly in perl, you could do something like this:
    while(<FH>) { my $line = $_; chomp($line); $line =~ /^[\d]+ rows in set \(([^\)]+)/; $retValue = $1 if (defined($1)); } close FH; print "The value is '$retValue'\n";
    My full test program is here:
    #!/usr/bin/perl -w # my $text=<<EOL; mysql> select * from shop; +---------+--------+-------+ | article | dealer | price | +---------+--------+-------+ | 0001 | A | 3.45 | | 0001 | B | 3.99 | | 0002 | A | 10.99 | | 0003 | B | 1.45 | | 0003 | C | 1.69 | | 0003 | D | 1.25 | | 0004 | D | 19.95 | +---------+--------+-------+ 7 rows in set (0.00 sec) EOL if ( ! open(FH,"echo '$text' |" ) ) { die "can't open\n"; } my $retValue = ''; while(<FH>) { my $line = $_; chomp($line); $line =~ /^[\d]+ rows in set \(([^\)]+)/; $retValue = $1 if (defined($1)); } close FH; print "The value is '$retValue'\n";
    To explain, the pattern match /^[\d]+ rows in set \(([^\)]+)/ captures everthing between the parens into $1.

Log In?
Username:
Password:

What's my password?
Create A New User
Domain Nodelet?
Node Status?
node history
Node Type: perlquestion [id://717593]
Approved by Corion
Front-paged by Corion
help
Chatterbox?
and the web crawler heard nothing...

How do I use this?Last hourOther CB clients
Other Users?
Others perusing the Monastery: (4)
As of 2024-03-29 11:08 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    No recent polls found