MySQL

The world's most popular open source database

Contact a MySQL Representative


  • MySQL.com
  • Developer Zone
  • Partners & Solutions
  • Customer Login
  • DevZone
  • Downloads
  • Documentation
  • Articles
  • Forums
  • Bugs
  • Forge
  • Blogs
 
  • You are currently browsing the archives for the MySQL 5.1 Features category.

  • Pages

    • About
    • Find and store the error return value in procedures or functions
  • Archives

    • August 2009
    • July 2009
    • June 2009
    • May 2009
    • April 2009
    • March 2009
    • February 2009
    • January 2009
    • December 2008
    • November 2008
    • October 2008
    • August 2008
    • July 2008
    • June 2008
    • May 2008
    • April 2008
  • Categories

    • MySQL 5.1 Features (3)
    • MySQL 5.4 New Features (2)
    • MySQL 6.0 New Features (5)
    • MySQL 6.x New Features (5)
    • News (8)
    • Personal Opinion (4)
    • Tiny Tweaks (10)
    • Uncategorized (19)



New Features In MySQL 6.x

Archive for the ‘MySQL 5.1 Features’ Category

MySQL’s TO_DAYS function

Monday, January 19th, 2009

I’ll try to clear up possible confusion about dates and MySQL’s TO_DAYS() function. TO_DAYS() works, correctly. TO_DAYS() assumes a year 0, correctly. There are indeed bugs, but only if you use MySQL extensions with partitions.

First: TO_DAYS() works, correctly. The MySQL Reference Manual says we use a proleptic Gregorian calendar, and that’s all explained with terms anyone can follow, in section “11.7. What Calendar Is Used By MySQL?”
http://dev.mysql.com/doc/refman/5.1/en/mysql-calendar.html
So we follow the Gregorian rules, not the Julian ones, without concerning ourselves about what happened in 1582 — just like DB2, just like the standard, not like Oracle. To make sure it’s okay, I wrote and ran this stored procedure:

DELIMITER //
SET @@sql_mode=ansi//
DROP procedure IF EXISTS p//
CREATE PROCEDURE p ()
BEGIN
  DECLARE days_in_month INT DEFAULT 31;
  DECLARE months_in_year INT DEFAULT 12;
  DECLARE expected_to_days INT;
  DECLARE pyear INT DEFAULT 1;
  DECLARE pmonth INT DEFAULT 1;
  DECLARE pday INT DEFAULT 1;
  DECLARE cyear VARCHAR(4);
  DECLARE year_month_day CHAR(10);

  /* Start with DATE string = '0001-01-01', the minimum legal value */
  SET year_month_day = pyear || '-' || pmonth || '-' || pday;
  /* Start with INT = 366 i.e. 366 days since '0000-01-01' */
  SET expected_to_days = 366;
  WHILE year_month_day < '9999-12-31' DO
    IF TO_DAYS(year_month_day) <> expected_to_days THEN
      SELECT 'error', year_month_day,TO_DAYS(year_month_day), expected_to_days;
      SET pyear = 9999; SET pmonth = 12; SET pday = 30;
      END IF;
    SET pday = pday + 1;
    IF pday > days_in_month THEN
      /* Overflowed days in month. Go forward 1 month. */
      SET pday = 1;
      SET pmonth = pmonth + 1;
      IF pmonth > months_in_year THEN
        /* Overflowed months in year. Go forward 1 year. */
        SET pmonth = 1;
        SET pyear = pyear + 1;
        END IF;
      IF pmonth = 1 THEN SET days_in_month = 31; END IF; /* January */
      IF pmonth = 2 THEN
        IF pyear MOD 4 = 0 AND (pyear MOD 100 <> 0 OR pyear MOD 400 = 0) THEN
          SET days_in_month = 29;
        ELSE
          SET days_in_month = 28;
          END IF;
        END IF;                                          /* February */
      IF pmonth = 3 THEN SET days_in_month = 31; END IF; /* March */
      IF pmonth = 4 THEN SET days_in_month = 30; END IF; /* April */
      IF pmonth = 5 THEN SET days_in_month = 31; END IF; /* May */
      IF pmonth = 6 THEN SET days_in_month = 30; END IF; /* June */
      IF pmonth = 7 THEN SET days_in_month = 31; END IF; /* July */
      IF pmonth = 8 THEN SET days_in_month = 31; END IF; /* August */
      IF pmonth = 9 THEN SET days_in_month = 30; END IF; /* September */
      IF pmonth =10 THEN SET days_in_month = 31; END IF; /* October */
      IF pmonth =11 THEN SET days_in_month = 30; END IF; /* November */
      IF pmonth =12 THEN SET days_in_month = 31; END IF; /* December */
      END IF;
    SET cyear = pyear;
    WHILE LENGTH(cyear) < 4 DO SET cyear = '0' || cyear; END WHILE; /* pad */
    SET year_month_day = cyear || '-' || pmonth || '-' || pday;
    SET expected_to_days = expected_to_days + 1;
    END WHILE;
  END//
CALL p()//

The procedure ranges over all valid dates between ‘0001-01-01′ and ‘9999-12-30′, while incrementing an integer that begins at 366. Each time the day goes up, the procedure calls TO_DAYS() and compares to the integer that we’re incrementing. If there’s an error, it prints ‘error’.

It doesn’t print ‘error’. Therefore there’s no error. QED.

This isn’t as comprehensive as what MySQL’s test suite does, but I like to do straightforward procedures so it’s obvious there’s nothing up my sleeve.

Second: TO_DAYS() assumes a year 0, correctly.

Astute readers may have noticed that I started with the assumption that TO_DAYS(’0001-01-01′ = 366. That’s correct because there was a year 0. I should explain that 0000 is 100% valid according to astronomical year numbering. Read your wikipedia: http://en.wikipedia.org/wiki/ISO_8601. Yes, Pope Gregory XIII didn’t use it, and yes, MySQL’s TO_DAYS(’0000-02-29′) etc. won’t use it, but we didn’t define those as valid dates for TO_DAYS(), so its only job is to be correct starting with 0001-01-01.

So, given that the MySQL manual says the start was really in year 0, the value of TO_DAYS(’0001-01-01′) should be the number of days in year 0. And how many is that according to Gregory’s leap-year rules? Well, 0 is divisible by 4, it’s divisible by 100, it’s divisible by 400. So it’s a leap year. So 366 is the right start.

Third: TO_DAYS() has associated bugs, but only if you use MySQL extensions.

Although this is basically a happy story, I do have to say that TO_DAYS works rather ungregorianly for dates which are outside the range 0001-01-01 to 9999-12-31, or dates which have MySQL’s extension that they can have day = 0, e.g. ‘2008-10-00′. This does result in the only legitimate bugs concerning TO_DAYS in the bugs.mysql.com
database:
Bug#20577 Partitions: use of to_days() function leads to selection failures
Bug#40972 Partition pruning can lead to crash for bad dates
We probably won’t fix Bug#20577 during the lifetime of MySQL version 5.1, but Bug#40972 (which is more serious) already has a fix available now. There also feature requests in bugs.mysql.com for extending the date range (Bug#8488, Bug#17902). I myself would love to see it go down to -4713-11-24 i.e. Julian day 0, but the 6.x worklog tasks don’t include such a feature.

I recommend the following for anyone who wants to know about date handling with various DBMSs:

“The Oracle Calendar” by Peter Gulutzan and Trudy Pelzer
http://www.orafaq.net/papers/dates_o.doc

“Dates in SQL” by Peter Gulutzan and Trudy Pelzer
http://www.informit.com/articles/article.aspx?p=30939

Posted in MySQL 5.1 Features | 1 Comment »

“Show profile” + “Information_schema.profiling”

Thursday, November 6th, 2008

Starting with version 5.1.28, there is a new table INFORMATION_SCHEMA.PROFILING and a new statement SHOW PROFILE(S). Basic information is in the reference manual and in an introductory article. But I don’t think that’s adequate for everyone. I’ll try here to give some non-basic information. I’ll assume that you read the manual, think of this as a supplement.

A bit of a caveat: I was totally against adding this feature, and some of my bias might show. But I’m not trying to argue about it. I do believe that once we add a feature we should explain it, and all I’m trying to do is explain here.

How it works

The data-gathering code, or “instrumentation”, goes approximately like this:
statement_begin:
start-and-setup-for-getting-info
Stage 1: collect-data()
bunch-of-code
Stage 2: collect-data()
bunch-of-code
Stage 3: collect-data()
…
end-and-put-info-in-buffer

And specifically the timing part of the collect-data() code looks like this:
In sql/sql_profile.cc:
”
void PROF_MEASUREMENT::collect()
{
time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */
#ifdef HAVE_GETRUSAGE
getrusage(RUSAGE_SELF, &rusage);
#endif
}
”

The my_getsystime() function gets time of day; the getrusage() function gets a little more; I’ll get into the details about ‘timing’ later.

So what’s happening is: if profiling is on (@@profiling==1), then, at each “stage” of processing for an SQL statement, MySQL gets the current time with a get-time-of-day function, and maybe gets a little more than that with getrusage().

This information is stored in memory. When you select from the PROFILING table, MySQL gets basic data about the query from elsewhere (things like “Query Id” or “Seq” are just counters and things like “function name” are straightforward), combines it with the timing information, and Bob’s your uncle, you have a display like this:

mysql> select query_id,seq,state,duration,source_function
       from information_schema.profiling where query_id = 6;
+----------+-----+--------------------+----------+-----------------------+
| query_id | seq | state              | duration | source_function       |
+----------+-----+--------------------+----------+-----------------------+
|        6 |   1 | starting           | 0.000565 | NULL                  |
|        6 |   2 | Opening tables     | 0.001148 | open_tables           |
|        6 |   3 | System lock        | 0.000137 | mysql_lock_tables     |
|        6 |   4 | Table lock         | 0.000222 | mysql_lock_tables     |
|        6 |   5 | init               | 0.000209 | mysql_select          |
|        6 |   6 | optimizing         | 0.027357 | optimize              |
|        6 |   7 | statistics         | 0.000398 | optimize              |
|        6 |   8 | preparing          | 0.000211 | optimize              |
|        6 |   9 | executing          | 0.001443 | exec                  |
|        6 |  10 | Sending data       | 0.000542 | exec                  |
|        6 |  11 | end                | 0.000213 | mysql_select          |
|        6 |  12 | query end          | 0.000143 | mysql_execute_command |
|        6 |  13 | freeing items      | 0.001860 | mysql_parse           |
|        6 |  14 | removing tmp table | 0.000900 | free_tmp_table        |
|        6 |  15 | closing tables     | 0.000142 | free_tmp_table        |
|        6 |  16 | logging slow query | 0.000139 | log_slow_statement    |
|        6 |  17 | cleaning up        | 0.000582 | dispatch_command      |
+----------+-----+--------------------+----------+-----------------------+
17 rows in set (0.00 sec)

There will be rows for the last 15 queries (15 is the default if you just “set @@profiling=1″) or perhaps as many as 100 (100 is the maximum value if you say “set @@profiling_history_size = 100″).

I’ll now explain what each of the above columns (query_id, seq, state, duration, source_function) is supposed to mean.

query_id

Whenever you enter a new statement, your “query identifier” goes up by 1. (MySQL people sometimes use the word “query” when the meaning is “statement”.)

This is a number within your session, not a global number, so each connection’s query_id value starts with 1.

SEQ

This is the “stage number” or “step number”. Each time the program reaches a new stage, this number goes up by 1.

state

By now the question might be: when does a new stage happen? MySQL has always (or at least, since before there was a “profiling” patch) had a function thd_set_proc_info() which it calls at different stages. The profiling feature is simply adding the timing functions to this thd_set_proc_info() and making it available via SHOW and SELECT. This piggybacking made the feature easier to add, but it means the stages aren’t always meaningful because they weren’t originally designed with query profiling in mind.

By using grep on the source code, I have been able to collect a list of the server functions which invoke get_thd_proc_info().

sql/item_func.cc:3393: thd_proc_info(thd, “User lock”);
sql/item_func.cc:3418: thd_proc_info(thd, 0);
sql/item_func.cc:3509: thd_proc_info(thd, “User lock”);
sql/item_func.cc:3552: thd_proc_info(thd, 0);
sql/item_func.cc:3737: thd_proc_info(thd, “User sleep”);
sql/item_func.cc:3749: thd_proc_info(thd, 0);
sql/log_event.cc:5926: thd_proc_info(thd, proc_info);
sql/log_event.cc:5979: thd_proc_info(thd, 0);
sql/log_event.cc:6101: thd_proc_info(thd, proc_info);
sql/log_event.cc:6135: thd_proc_info(thd, 0);
sql/sql_delete.cc:62: thd_proc_info(thd, “init”);
sql/sql_delete.cc:253: thd_proc_info(thd, “updating”);
sql/sql_delete.cc:336: thd_proc_info(thd, “end”);
sql/sql_delete.cc:582: thd_proc_info(thd, “deleting from main table”);
sql/sql_delete.cc:897: thd_proc_info(thd, “deleting from reference tables”);
sql/sql_delete.cc:906: thd_proc_info(thd, “end”);
sql/sql_class.cc:264:const char *set_thd_proc_info(THD *thd, const char *info,
sql/sp_head.cc:2734: thd_proc_info(thd, “closing tables”);
sql/sp_head.cc:2737: thd_proc_info(thd, 0);
sql/lock.cc:258: thd_proc_info(thd, “System lock”);
sql/lock.cc:269: thd_proc_info(thd, “Table lock”);
sql/lock.cc:317: thd_proc_info(thd, 0);
sql/lock.cc:332: thd_proc_info(thd, 0);
sql/sql_base.cc:940: thd_proc_info(thd, “Flushing tables”);
sql/sql_base.cc:1008: thd_proc_info(thd, 0);
sql/sql_base.cc:2140: thd_proc_info(thd, “Waiting for table”);
sql/sql_base.cc:2160: thd_proc_info(thd, proc_info);
sql/sql_base.cc:3532: thd_proc_info(thd, “Waiting for tables”);
sql/sql_base.cc:3548: thd_proc_info(thd, “Reopen tables”);
sql/sql_base.cc:3553: thd_proc_info(thd, 0);
sql/sql_base.cc:4450: thd_proc_info(thd, “Opening tables”);
sql/sql_base.cc:4729: thd_proc_info(thd, 0);
sql/sql_base.cc:4878: thd_proc_info(thd, “Opening table”);
sql/sql_base.cc:4918: thd_proc_info(thd, 0);
sql/sql_base.cc:8511: thd_proc_info(thd, “FULLTEXT initialization”);
sql/sql_view.cc:669: thd_proc_info(thd, “end”);
sql/sql_update.cc:235: thd_proc_info(thd, “init”);
sql/sql_update.cc:464: thd_proc_info(thd, “Searching rows for update”);
sql/sql_update.cc:533: thd_proc_info(thd, “Updating”);
sql/sql_update.cc:766: thd_proc_info(thd, “end”);
sql/sql_update.cc:1260: thd_proc_info(thd, “updating main table”);
sql/sql_update.cc:1974: thd_proc_info(thd, “updating reference tables”);
sql/sql_update.cc:1986: thd_proc_info(thd, “end”);
sql/sql_insert.cc:618: thd_proc_info(thd, “init”);
sql/sql_insert.cc:703: thd_proc_info(thd, “update”);
sql/sql_insert.cc:923: thd_proc_info(thd, “end”);
sql/sql_insert.cc:1796: thd_proc_info(thd, “waiting for delay_list”);
sql/sql_insert.cc:1878: thd_proc_info(thd, “Creating delayed handler”);
sql/sql_insert.cc:1924: thd_proc_info(thd, “waiting for handler open”);
sql/sql_insert.cc:1930: thd_proc_info(thd, “got old table”);
sql/sql_insert.cc:2007: thd_proc_info(client_thd, “waiting for handler lock”);
sql/sql_insert.cc:2013: thd_proc_info(client_thd, “got handler lock”);
sql/sql_insert.cc:2031: thd_proc_info(client_thd, “allocating local table”);
sql/sql_insert.cc:2116: thd_proc_info(thd, “waiting for handler insert”);
sql/sql_insert.cc:2120: thd_proc_info(thd, “storing row into queue”);
sql/sql_insert.cc:2366: thd_proc_info(&(di->thd), “Waiting for INSERT”);
sql/sql_insert.cc:2401: thd_proc_info(&(di->thd), 0);
sql/sql_insert.cc:2543: thd_proc_info(&thd, “upgrading lock”);
sql/sql_insert.cc:2556: thd_proc_info(&thd, “insert”);
sql/sql_insert.cc:2694: thd_proc_info(&thd, “reschedule”);
sql/sql_insert.cc:2715: thd_proc_info(&thd, “insert”);
sql/sql_insert.cc:2721: thd_proc_info(&thd, 0);
sql/slave.cc:1054: thd_proc_info(thd, “Creating table from master dump”);
sql/slave.cc:1069: thd_proc_info(thd, “Opening master dump table”);
sql/slave.cc:1085: thd_proc_info(thd, “Reading master dump table data”);
sql/slave.cc:1097: thd_proc_info(thd, “Rebuilding the index on master dump table”);
sql/slave.cc:1586: thd_proc_info(thd, “Waiting for the next event in relay log”);
sql/slave.cc:1588: thd_proc_info(thd, “Waiting for master update”);
sql/slave.cc:2311: thd_proc_info(thd, “Connecting to master”);
sql/slave.cc:2338: thd_proc_info(thd, “Checking master version”);
sql/slave.cc:2347: thd_proc_info(thd, “Registering slave on master”);
sql/slave.cc:2377: thd_proc_info(thd, “Requesting binlog dump”);
sql/slave.cc:2408: thd_proc_info(thd, “Waiting for master to send event”);
sql/slave.cc:2452: thd_proc_info(thd, “Queueing master event to the relay log”);
sql/slave.cc:2527: thd_proc_info(thd, “Waiting for slave mutex on exit”);
sql/slave.cc:2714: thd_proc_info(thd, “Reading event from the relay log”);
sql/slave.cc:2801: thd_proc_info(thd, “Waiting for slave mutex on exit”);
sql/sql_cache.cc:760: thd_proc_info(thd, “storing result in query cache”);
sql/sql_cache.cc:813: thd_proc_info(thd, “storing result in query cache”);
sql/sql_cache.cc:1262: thd_proc_info(thd, “checking query cache for query”);
sql/sql_cache.cc:1346: thd_proc_info(thd, “checking privileges on cached query”);
sql/sql_cache.cc:1441: thd_proc_info(thd, “sending cached result to client”);
sql/sql_cache.cc:1518: thd_proc_info(thd, “invalidating query cache entries (table list)”);
sql/sql_cache.cc:1544: thd_proc_info(thd, “invalidating query cache entries (table)”);
sql/sql_class.h:1298: Set it using the thd_proc_info(THD *thread, const char *message)
sql/sql_parse.cc:386: thd_proc_info(thd, “Execution of init_command”);
sql/sql_parse.cc:447: thd_proc_info(thd, 0);
sql/sql_parse.cc:1575: thd_proc_info(thd, “cleaning up”);
sql/sql_parse.cc:1577: thd_proc_info(thd, 0);
sql/sql_parse.cc:1608: thd_proc_info(thd, “logging slow query”);
sql/sql_parse.cc:1618: thd_proc_info(thd, “logging slow query”);
sql/sql_parse.cc:3220: thd_proc_info(thd, “init”);
sql/sql_parse.cc:4799: thd_proc_info(thd, “query end”);
sql/sql_parse.cc:5037: thd_proc_info(thd, “checking permissions”);
sql/sql_parse.cc:5805: thd_proc_info(thd, “freeing items”);
sql/repl_failsafe.cc:104: thd_proc_info(thd, “Thread initialized”);
sql/repl_failsafe.cc:619: thd_proc_info(thd, “Processing request”);
sql/repl_failsafe.cc:974: thd_proc_info(thd, “purging old relay logs”);
sql/repl_failsafe.cc:1001: thd_proc_info(thd, “starting slave”);
sql/repl_failsafe.cc:1013: thd_proc_info(thd, 0);
sql/sql_repl.cc:658: thd_proc_info(thd, “Sending binlog event to slave”);
sql/sql_repl.cc:696: thd_proc_info(thd, “Finished reading one binlog; switching to next binlog”);
sql/sql_repl.cc:742: thd_proc_info(thd, “Waiting to finalize termination”);
sql/sql_repl.cc:749: thd_proc_info(thd, “Waiting to finalize termination”);
sql/sql_repl.cc:903: thd_proc_info(thd, “Killing slave”);
sql/sql_repl.cc:930: thd_proc_info(thd, 0);
sql/sql_repl.cc:1089: thd_proc_info(thd, “Changing master”);
sql/sql_repl.cc:1220: thd_proc_info(thd, “Purging old relay logs”);
sql/sql_repl.cc:1281: thd_proc_info(thd, 0);
sql/sql_select.cc:762: thd_proc_info(thd, “optimizing”);
sql/sql_select.cc:944: thd_proc_info(thd, “statistics”);
sql/sql_select.cc:954: thd_proc_info(thd, “preparing”);
sql/sql_select.cc:1408: thd_proc_info(thd, “Creating tmp table”);
sql/sql_select.cc:1458: thd_proc_info(thd, “Sorting for group”);
sql/sql_select.cc:1479: thd_proc_info(thd, “Sorting for order”);
sql/sql_select.cc:1638: thd_proc_info(thd, “executing”);
sql/sql_select.cc:1777: thd_proc_info(thd, “Copying to tmp table”);
sql/sql_select.cc:1904: thd_proc_info(thd, “Creating sort index”);
sql/sql_select.cc:1918: thd_proc_info(thd, “Copying to group table”);
sql/sql_select.cc:1977: thd_proc_info(thd, “Removing duplicates”);
sql/sql_select.cc:2040: thd_proc_info(thd, “Sorting result”);
sql/sql_select.cc:2177: thd_proc_info(thd, “Sending data”);
sql/sql_select.cc:2337: thd_proc_info(thd, “init”);
sql/sql_select.cc:2382: thd_proc_info(thd, “end”);
sql/sql_select.cc:10527: thd_proc_info(thd, “removing tmp table”);
sql/sql_select.cc:10549: thd_proc_info(thd, save_proc_info);
sql/sql_select.cc:10583: thd_proc_info(thd, “converting HEAP to MyISAM”);
sql/sql_select.cc:10647: thd_proc_info(thd, (!strcmp(save_proc_info,”Copying to tmp table”) ?
sql/sql_select.cc:10660: thd_proc_info(thd, save_proc_info);
sql/sql_table.cc:3517: thd_proc_info(thd, “creating table”);
sql/sql_table.cc:3586: thd_proc_info(thd, “After create”);
sql/sql_table.cc:5096: thd_proc_info(thd, “discard_or_import_tablespace”);
sql/sql_table.cc:5113: thd_proc_info(thd, “end”);
sql/sql_table.cc:6068: thd_proc_info(thd, “init”);
sql/sql_table.cc:6271: thd_proc_info(thd, “setup”);
sql/sql_table.cc:6327: thd_proc_info(thd, “rename”);
sql/sql_table.cc:6724: thd_proc_info(thd, “copy to tmp table”);
sql/sql_table.cc:6898: thd_proc_info(thd, “rename result table”);
sql/sql_table.cc:7013: thd_proc_info(thd, “end”);
sql/mysql_priv.h:619:#define thd_proc_info(thd, msg) set_thd_proc_info(thd, msg, __func__, __FILE__, __LINE__)
sql/mysql_priv.h:681: The meat of thd_proc_info(THD*, char*), a macro that packs the last
sql/mysql_priv.h:685:const char *set_thd_proc_info(THD *thd, const char *info,
sql/mysql_priv.h.pp:1694:const char *thd_proc_info(void* thd, const char *info);
sql/mysql_priv.h.pp:2394:const char *set_thd_proc_info(THD *thd, const char *info,
storage/csv/ha_tina.cc:1552: old_proc_info= thd_proc_info(thd, “Checking table”);
storage/csv/ha_tina.cc:1582: thd_proc_info(thd, old_proc_info);
storage/myisam/ha_myisam.cc:752: thd_proc_info(thd, “Checking table”);
storage/myisam/ha_myisam.cc:826: thd_proc_info(thd, old_proc_info);
storage/myisam/ha_myisam.cc:1112: thd_proc_info(thd, buf);
storage/myisam/ha_myisam.cc:1115: thd_proc_info(thd, “Repair done”); // to reset proc_info, as
storage/myisam/ha_myisam.cc:1120: thd_proc_info(thd, “Repair by sorting”);
storage/myisam/ha_myisam.cc:1127: thd_proc_info(thd, “Repair with keycache”);
storage/myisam/ha_myisam.cc:1141: thd_proc_info(thd, “Sorting index”);
storage/myisam/ha_myisam.cc:1149: thd_proc_info(thd, “Analyzing”);
storage/myisam/ha_myisam.cc:1156: thd_proc_info(thd, “Saving state”);
storage/myisam/ha_myisam.cc:1194: thd_proc_info(thd, old_proc_info);
storage/myisam/ha_myisam.cc:1409: thd_proc_info(thd, “Creating index”);
storage/myisam/ha_myisam.cc:1434: thd_proc_info(thd, save_proc_info);
storage/archive/ha_archive.cc:1553: old_proc_info= thd_proc_info(thd, “Checking table”);
storage/archive/ha_archive.cc:1568: thd_proc_info(thd, old_proc_info);

So there you go, now you know what the “state” values are, except for a few like “Resuming”. And for more information, all you have to do is read the above source files. Of course, the line numbers will change frequently and the calls to set_thd_proc_info() will change occasionally.

duration

The my_getsystime() function in sql/my_getsystime.c gets time of day with one of:
clock_gettime() available on many Unix systems
QueryPerformanceCounter() Windows only
NXGetTime() NetWare only
gettimeofday() the default if there’s nothing else
All these time-of-day functions are slow on most platforms, but they only get called a few times per statement, because a typical statement has ten or fewer “Stages”. And they’re all good for microsecond measurements.

To get “Duration”, MySQL just subtracts time-of-day [for the previous stage] from time-of-day [for the current stage].

The first (”starting”) row has the duration since the statement execution started, so it doesn’t include some network-IO overhead.

source_function

I tend to think that “state” is more explanatory than “source_function”, but if you really need to get an exact idea about the stage that’s been reached, source_function and source_line are the things to look at. The reference is of course to the source code at build time, so if you pull and build at different times, or depend on a binary distribution, you might have a bit of trouble with these values.

The columns that come from getrusage()

Remember that the lines for ‘timing’ invoked a get-time-of-day function, and then this:
#ifdef HAVE_GETRUSAGE
getrusage(RUSAGE_SELF, &rusage);
#endif
which means “call the operating system’s getrusage() function f it’s there”.

The getrusage() function is available on most operating systems but the MySQL names are all different from the getrusage names. Here is a handy chart:

MYSQL COLUMN NAME               GETRUSAGE FIELD NAME
CPU_USER decimal(9,6)           ru_utime
CPU_SYSTEM decimal(9,6)         ru_stime
CONTEXT_VOLUNTARY               ru_nvcsw
CONTEXT_INVOLUNTARY int(20)     ru_nivcsw
BLOCK_OPS_IN int(20)            ru_inblock
BLOCK_OPS_OUT int(20)           ru_oublock
MESSAGES_SENT int(20)           ru_msgend
MESSAGES_RECEIVED int(20)       ru_msgrcv
PAGE_FAULTS_MAJOR int(20)       ru_majflt
PAGE_FAULTS_MINOR int(20)       ru_minflt
SWAPS int(20)                   ru_nswap

The possibly interesting values are PAGE_FAULTS_MAJOR (which tells you if the operating system had to do a disk read because it didn’t have a copy of the disk block in its memory), CONTEXT_VOLUNTARY (which may help you guess the number of “waits” i.e. how many times a thread had to wait for something), and BLOCK_OPS_IN + BLOCK_OPS_OUT (which give a good hint about how active the disk is).

Some things may need emphasis for a MySQL context.

1 It does not work on Windows!
There is a Windows-API function to get the number of page faults and some memory information: GetProcessMemoryInfo (http://msdn.microsoft.com/en-us/library/ms683219(VS.85).aspx). And GetProcessTimes might give something like ru_utime + ru_stime. So we could get at least some of the getrusage() data. But we don’t.

2 It’s per process not per thread!
Since MySQL tends to use a thread-per-connection model, it might be most interesting to know “how long did this process take for this thread” rather than “how long did it take for the whole process (which includes other threads)”. This way, if some other job interrupts, you’ll see the other job’s time rather than your own. Linux is moving towards per-thread accounting (my Brazilian colleague informed me it’s already working fine with the 2.6.25 kernel), but on a busy system your times may be misleading.

3 It gives estimates that are useless for short measurements!
Usually getrusage() is getting information that the operating system deposited the last time there was a ‘timer tick’, which could be as much as 1/100 seconds ago. Some operating systems tick 1000 times per second instead of 100 times per second, and Solaris has “microstate accounting” which means it’s precise. But as a general rule you can’t trust getrusage() results for high precision.

All of these observations are okay, given the purpose of the profile feature. But I thought you should know about them.

The future

If we decide to remove a feature, we always give plenty of warning with a “deprecation notice”. At time of writing there is no deprecation notice for the profiling feature.

Posted in MySQL 5.1 Features | 3 Comments »

MySQL Stored Procedures book — Corrected

Sunday, May 25th, 2008

Long ago I wrote a 100-page book on MySQL 5.0 stored procedures. It’s on our dev-zone pages. But it’s out of date. In 2006 I made some corrections for MySQL 5.1. It took me a long time to publish the revised book, but here it is: http://blogs.mysql.com/peterg/files/2008/05/book01.pdf.

Posted in MySQL 5.1 Features | 2 Comments »

New Features In MySQL 6.x is proudly powered by WordPress MU running on Blogs.mysql.com.
Entries (RSS) and Comments (RSS).