profiling_slow format is unparseable
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona Server moved to https://jira.percona.com/projects/PS |
Fix Released
|
Medium
|
Alexey Kopytov | ||
Bug Description
The format shown on http://
# 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_
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://
Related branches
- Vadim Tkachenko: Approve
- Fred Linhoss (community): Approve (documentation)
- Percona: Needs Information
-
Diff: 411 lines (+226/-47)3 files modifiedmysql-test/profiling_slow.patch/percona_bug643149.result (+16/-0)
mysql-test/profiling_slow.patch/percona_bug643149.test (+46/-0)
profiling_slow.patch (+164/-47)
Changed in percona-server: | |
status: | New → Confirmed |
importance: | Undecided → Medium |
assignee: | nobody → Oleg Tsarev (tsarev) |
milestone: | none → 5.1-13.0 |
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 |
The same happens when InnoDB starts and attaches to existing shared buffer pool.
A lot of time is spent in ut0rnd. ic:171 ut0rnd. ic: No such file or directory.
0x00000000007d8b73 in ut_fold_ulint_pair (chunk=0x913e1d8, mem_size=<value optimized out>) at ./include/
171 ./include/
in ./include/ut0rnd.ic