profiling_slow format is unparseable

Bug #643149 reported by Baron Schwartz on 2010-09-19
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to
Fix Released
Alexey Kopytov
Nominated for Release-5.1.54-12 by Alexey Kopytov

Bug Description

The format shown on 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

Related branches

Changed in percona-server:
status: New → Confirmed
importance: Undecided → Medium
assignee: nobody → Oleg Tsarev (tsarev)
milestone: none → 5.1-13.0
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

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

Percona now uses JIRA for bug reports so this bug report is migrated to:

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

Other bug subscribers