profiling_slow format is unparseable

Bug #643149 reported by Baron Schwartz
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Medium
Alexey Kopytov
Nominated for Release-5.1.54-12 by Alexey Kopytov

Bug Description

The format shown on http://www.percona.com/docs/wiki/patches:profiling_slow is not compatible with normal slow-log parsing:

# PROFILE_VALUES starting: 0.000101, (cpu: 0.000096) checking permissions: 0.000012, (cpu: 0.000012) Opening tables: 0.000155, (cpu: 0.000156) System lock: 0.000008, (cpu: 0.000007) Table lock: 0.000023, (cpu: 0.000023) init: 0.000027, (cpu: 0.000027) optimizing: 0.000006, (cpu: 0.000006) statistics: 0.000014, (cpu: 0.000014) preparing: 0.000010, (cpu: 0.000011) Creating tmp table: 0.000051, (cpu: 0.000052) executing: 0.000054, (cpu: 0.000053) Copying to tmp table: 0.122474, (cpu: 0.122135) converting HEAP to MyISAM: 0.094106, (cpu: 0.093955) Copying to tmp table on disk: 1.302360, (cpu: 1.300129) Sending data: 3.012816, (cpu: 2.332287) end: 0.000011, (cpu: 0.000005) removing tmp table: 0.021657, (cpu: 0.021519) end: 0.000014, (cpu: 0.000007) end: 0.000034, (cpu: 0.000034) query end: 0.000006, (cpu: 0.000006) freeing items: 0.000013, (cpu: 0.000013) closing tables: 0.000007, (cpu: 0.000007) logging slow query: 0.000003, (cpu: 0.000003)
# PROFILE_TOTALS Total: 4.553962 (cpu: 3.870556)

The slow-log format is generally

# Name: value Name: value [.....]

Each "name" and "value" is a string of non-whitespace characters. Any change to this makes log-parsing harder and more expensive for tools such as mk-query-digest. I would suggest something like the following:

# Profile_starting: 0.000101 Profile_starting_cpu: 0.000096 Profile_freeing_items: 0.000013 Profile_freeing_items_cpu: 0.000013

There are two problems with changing this: 1) it breaks backwards compatibility, which is not a big deal because probably no tools exist to parse it in its current form; and 2) it makes the log much bigger. However, I think it's probably the right thing to do. Any further patches such as ones to include INDEX_STATISTICS into the slow query log need to be designed very carefully! See the comments on http://ebergen.net/wordpress/2010/01/19/table-statistics-draft-2-the-slow-query-log/

Related branches

Changed in percona-server:
status: New → Confirmed
importance: Undecided → Medium
assignee: nobody → Oleg Tsarev (tsarev)
milestone: none → 5.1-13.0
Revision history for this message
Vadim Tkachenko (vadim-tk) wrote :

The same happens when InnoDB starts and attaches to existing shared buffer pool.

A lot of time is spent in
0x00000000007d8b73 in ut_fold_ulint_pair (chunk=0x913e1d8, mem_size=<value optimized out>) at ./include/ut0rnd.ic:171
171 ./include/ut0rnd.ic: No such file or directory.
        in ./include/ut0rnd.ic

Revision history for this message
Vadim Tkachenko (vadim-tk) wrote :

Previous comment is to another bug

Changed in percona-server:
assignee: Oleg Tsarev (tsarev) → Alexey Kopytov (akopytov)
Changed in percona-server:
status: Confirmed → In Progress
Changed in percona-server:
status: In Progress → Fix Committed
Changed in percona-server:
status: Fix Committed → Fix Released
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1162

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.