-- 5.7 rm -rf 98771/ bin/mysqld --initialize-insecure --basedir=$PWD --datadir=$PWD/98771 --log-error-verbosity=3 bin/mysqld --no-defaults --basedir=$PWD --datadir=$PWD/98771 --core-file --socket=/tmp/mysql_ushastry.sock --port=3333 --log-error=$PWD/98771/log.err --log-error-verbosity=3 --secure-file-priv="" --skip-name-resolve 2>&1 & create database jsontest; use jsontest; source /tmp/mysql5716_clone.sql; pager grep non-sence select * from geodata; select json_col from geodata; -- 5.7.11 mysql> pager grep non-sence PAGER set to 'grep non-sence' mysql> select * from geodata; 1 row in set (0.19 sec) mysql> select * from geodata; 1 row in set (0.19 sec) mysql> select json_col from geodata; 1 row in set (0.19 sec) mysql> select * from geodata; 1 row in set (0.21 sec) mysql> select json_col from geodata; 1 row in set (0.19 sec) - perf (perf record -g -F 10 -o mysql-5_7_11.g.perf -p $PID -- sleep 20) perf report -i mysql-5_7_11.g.perf|c++filt # ======== # captured on: Fri Feb 28 10:56:45 2020 # hostname : hod03 # os release : 3.8.13-98.2.2.el7uek.x86_64 # perf version : 3.8.13-98.2.2.el7uek.x86_64 # arch : x86_64 # nrcpus online : 32 # nrcpus avail : 32 # cpudesc : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz # cpuid : GenuineIntel,6,62,4 # total memory : 264098836 kB # cmdline : /usr/libexec/perf.3.8.13-98.2.2.el7uek.x86_64 record -g -F 10 -o mysql-5_7_11.g.perf -p 11712 -- sleep 20 # event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, id = { 117, 118, 119, 120, 121, 122, 123, 124, 125, 126, 127, 128, 129, 130, 131, 132, 133, 134, 135, 136, 137, 138, 139, 140, 141, 142, 143, 144 } # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5 # ======== # # Samples: 75 of event 'cycles' # Event count (approx.): 9462311472 # # Overhead Command Shared Object Symbol # ........ ....... ................. .................................... # 93.54% mysqld mysqld [.] mtr_t::Command::release_all() | --- mtr_t::Command::release_all() mtr_t::commit() btr_copy_blob_prefix(unsigned char*, unsigned long, unsigned long, unsigned long, unsigned long) btr_copy_externally_stored_field(unsigned long*, unsigned char const*, page_size_t const&, unsigned long, mem_block_info_t*) row_sel_store_mysql_field_func(unsigned char*, row_prebuilt_t*, unsigned char const*, unsigned long const*, unsigned long, mysql_row_templ_t const*) row_sel_store_mysql_rec(unsigned char*, row_prebuilt_t*, unsigned char const*, dtuple_t const*, unsigned long, dict_index_t const*, unsigned long const*) row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) ha_innobase::index_first(unsigned char*) ha_innobase::rnd_next(unsigned char*) handler::ha_rnd_next(unsigned char*) rr_sequential(READ_RECORD*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 5.48% mysqld mysqld [.] dtoa.clone.0 | --- dtoa.clone.0 my_gcvt wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.25% mysqld [kernel.kallsyms] [k] native_write_msr_safe | --- native_write_msr_safe intel_pmu_enable_all x86_pmu_enable perf_pmu_enable perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule | |--65.12%-- read_events | sys_io_getevents | system_call_fastpath | 0x7fe30b463644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | |--21.01%-- futex_wait_queue_me | futex_wait | do_futex | sys_futex | system_call_fastpath | pthread_cond_timedwait@@GLIBC_2.3.2 | os_event::wait_time_low(unsigned long, long) | | | |--57.09%-- dict_stats_thread | | start_thread | | | |--42.79%-- srv_monitor_thread | | start_thread | --0.12%-- [...] | |--13.86%-- schedule_hrtimeout_range_clock | schedule_hrtimeout_range | poll_schedule_timeout | do_sys_poll | sys_poll | system_call_fastpath | 0x7fe30a32d00d | vio_socket_io_wait | vio_read | net_read_raw_loop(st_net*, unsigned long) | net_read_packet_header(st_net*) | my_net_read | Protocol_classic::read_packet() | Protocol_classic::get_command(COM_DATA*, enum_server_command*) | do_command(THD*) | handle_connection | pfs_spawn_thread | start_thread --0.01%-- [...] 0.15% mysqld [kernel.kallsyms] [k] finish_task_switch | --- finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fe30b463644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.14% mysqld [kernel.kallsyms] [k] perf_ctx_unlock | --- perf_ctx_unlock | |--51.47%-- __perf_event_task_sched_in | finish_task_switch | __schedule | schedule | do_nanosleep | hrtimer_nanosleep | sys_nanosleep | system_call_fastpath | 0x7fe30b67399d | srv_master_thread | start_thread | --48.53%-- perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) lock_wait_timeout_thread start_thread 0.09% mysqld [kernel.kallsyms] [k] futex_wait_queue_me | --- futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) srv_error_monitor_thread start_thread 0.08% mysqld [kernel.kallsyms] [k] read_events | --- read_events sys_io_getevents system_call_fastpath 0x7fe30b463644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.08% mysqld [kernel.kallsyms] [k] perf_pmu_rotate_start.isra.41 | --- perf_pmu_rotate_start.isra.41 perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fe30b463644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.07% mysqld [kernel.kallsyms] [k] __perf_event_task_sched_in | --- __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fe30b463644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.06% mysqld [kernel.kallsyms] [k] perf_event_context_sched_in | --- perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) buf_flush_page_cleaner_coordinator start_thread 0.06% mysqld [kernel.kallsyms] [k] __schedule | --- __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) ib_wqueue_timedwait(ib_wqueue_t*, long) fts_optimize_thread(void*) start_thread # # (For a higher level overview, try: perf report --sort comm,dso) # -- 5.7.16 mysql> pager grep non-sence PAGER set to 'grep non-sence' mysql> select * from geodata; 1 row in set (0.20 sec) mysql> select json_col from geodata; 1 row in set (0.19 sec) mysql> select * from geodata; 1 row in set (0.20 sec) mysql> select json_col from geodata; 1 row in set (0.18 sec) mysql> select json_col from geodata; 1 row in set (0.19 sec) mysql> select * from geodata; 1 row in set (0.20 sec) perf record -g -F 10 -o mysql-5_7.16.g.perf -p 13837 -- sleep 20 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.051 MB mysql-5_7.16.g.perf (~2228 samples) ] perf report -i mysql-5_7_11.g.perf|c++filt perf report -i mysql-5_7.16.g.perf|c++filt # ======== # captured on: Fri Feb 28 11:19:13 2020 # hostname : hod03 # os release : 3.8.13-98.2.2.el7uek.x86_64 # perf version : 3.8.13-98.2.2.el7uek.x86_64 # arch : x86_64 # nrcpus online : 32 # nrcpus avail : 32 # cpudesc : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz # cpuid : GenuineIntel,6,62,4 # total memory : 264098836 kB # cmdline : /usr/libexec/perf.3.8.13-98.2.2.el7uek.x86_64 record -g -F 10 -o mysql-5_7.16.g.perf -p 13837 -- sleep 20 # event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, id = { 145, 146, 147, 148, 149, 150, 151, 152, 153, 154, 155, 156, 157, 158, 159, 160, 161, 162, 163, 164, 165, 166, 167, 168, 169, 170, 171, 172 } # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5 # ======== # # Samples: 74 of event 'cycles' # Event count (approx.): 20134408217 # # Overhead Command Shared Object Symbol # ........ ....... ................. ................................. # 71.64% mysqld mysqld [.] dtoa.clone.0 | --- dtoa.clone.0 my_gcvt wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 27.93% mysqld [kernel.kallsyms] [k] lookup_ioctx | --- lookup_ioctx sys_io_getevents system_call_fastpath 0x7f97f60d5644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.13% mysqld [kernel.kallsyms] [k] native_write_msr_safe | --- native_write_msr_safe intel_pmu_enable_all x86_pmu_enable perf_pmu_enable perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule | |--70.44%-- read_events | sys_io_getevents | system_call_fastpath | 0x7f97f60d5644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | |--29.54%-- futex_wait_queue_me | futex_wait | do_futex | sys_futex | system_call_fastpath | pthread_cond_timedwait@@GLIBC_2.3.2 | os_event::wait_time_low(unsigned long, long) | | | |--55.63%-- ib_wqueue_timedwait(ib_wqueue_t*, long) | | fts_optimize_thread(void*) | | start_thread | | | |--44.29%-- dict_stats_thread | | start_thread | --0.08%-- [...] --0.01%-- [...] 0.07% mysqld [kernel.kallsyms] [k] __perf_event_task_sched_in | --- __perf_event_task_sched_in finish_task_switch __schedule schedule | |--50.38%-- read_events | sys_io_getevents | system_call_fastpath | 0x7f97f60d5644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | --49.62%-- futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) srv_monitor_thread start_thread 0.06% mysqld [kernel.kallsyms] [k] __ticket_spin_unlock | --- __ticket_spin_unlock | |--53.80%-- finish_task_switch | __schedule | schedule | read_events | sys_io_getevents | system_call_fastpath | 0x7f97f60d5644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | --46.20%-- perf_ctx_unlock perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) buf_flush_page_cleaner_coordinator start_thread 0.06% mysqld [kernel.kallsyms] [k] perf_pmu_rotate_start.isra.41 | --- perf_pmu_rotate_start.isra.41 | |--59.95%-- perf_event_context_sched_in | __perf_event_task_sched_in | finish_task_switch | __schedule | schedule | read_events | sys_io_getevents | system_call_fastpath | 0x7f97f60d5644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | --40.05%-- __perf_event_task_sched_in finish_task_switch __schedule schedule schedule_hrtimeout_range_clock schedule_hrtimeout_range poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath 0x7f97f4f9f00d vio_socket_io_wait vio_read net_read_raw_loop(st_net*, unsigned long) net_read_packet(st_net*, unsigned long*) my_net_read Protocol_classic::read_packet() Protocol_classic::get_command(COM_DATA*, enum_server_command*) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.05% mysqld [kernel.kallsyms] [k] lock_hrtimer_base.isra.19 | --- lock_hrtimer_base.isra.19 hrtimer_try_to_cancel do_nanosleep hrtimer_nanosleep sys_nanosleep system_call_fastpath 0x7f97f62e599d srv_master_thread start_thread 0.04% mysqld [kernel.kallsyms] [k] finish_task_switch | --- finish_task_switch __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) srv_error_monitor_thread start_thread 0.03% mysqld [kernel.kallsyms] [k] __schedule | --- __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) lock_wait_timeout_thread start_thread # # (For a higher level overview, try: perf report --sort comm,dso) # -- 5.7.21 mysql> pager grep non-sence PAGER set to 'grep non-sence' mysql> select * from geodata; 1 row in set (0.19 sec) mysql> select json_col from geodata; 1 row in set (0.19 sec) mysql> select * from geodata; 1 row in set (0.19 sec) mysql> select json_col from geodata; 1 row in set (0.19 sec) - perf report -i mysql-5_7.21.g.perf|c++filt # ======== # captured on: Fri Feb 28 11:31:58 2020 # hostname : hod03 # os release : 3.8.13-98.2.2.el7uek.x86_64 # perf version : 3.8.13-98.2.2.el7uek.x86_64 # arch : x86_64 # nrcpus online : 32 # nrcpus avail : 32 # cpudesc : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz # cpuid : GenuineIntel,6,62,4 # total memory : 264098836 kB # cmdline : /usr/libexec/perf.3.8.13-98.2.2.el7uek.x86_64 record -g -F 10 -o mysql-5_7.21.g.perf -p 14892 -- sleep 20 # event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, id = { 201, 202, 203, 204, 205, 206, 207, 208, 209, 210, 211, 212, 213, 214, 215, 216, 217, 218, 219, 220, 221, 222, 223, 224, 225, 226, 227, 228 } # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5 # ======== # # Samples: 73 of event 'cycles' # Event count (approx.): 12977456596 # # Overhead Command Shared Object Symbol # ........ ....... ................. ................................. # 99.21% mysqld libc-2.17.so [.] __memmove_ssse3_back | --- __memmove_ssse3_back btr_copy_externally_stored_field(unsigned long*, unsigned char const*, page_size_t const&, unsigned long, mem_block_info_t*) row_sel_store_mysql_field_func(unsigned char*, row_prebuilt_t*, unsigned char const*, unsigned long const*, unsigned long, mysql_row_templ_t const*, unsigned long) row_sel_store_mysql_rec(unsigned char*, row_prebuilt_t*, unsigned char const*, dtuple_t const*, unsigned long, dict_index_t const*, unsigned long const*, bool) row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) ha_innobase::index_first(unsigned char*) ha_innobase::rnd_next(unsigned char*) handler::ha_rnd_next(unsigned char*) rr_sequential(READ_RECORD*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.25% mysqld [kernel.kallsyms] [k] perf_pmu_rotate_start.isra.41 | --- perf_pmu_rotate_start.isra.41 | |--87.78%-- perf_event_context_sched_in | __perf_event_task_sched_in | finish_task_switch | __schedule | schedule | | | |--51.34%-- futex_wait_queue_me | | futex_wait | | do_futex | | sys_futex | | system_call_fastpath | | pthread_cond_timedwait@@GLIBC_2.3.2 | | os_event::wait_time_low(unsigned long, long) | | | | | |--56.70%-- buf_flush_page_cleaner_coordinator | | | start_thread | | | | | --43.30%-- lock_wait_timeout_thread | | start_thread | | | --48.66%-- read_events | sys_io_getevents | system_call_fastpath | 0x7fa3f9a59644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | --12.22%-- __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fa3f9a59644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.16% mysqld [kernel.kallsyms] [k] native_write_msr_safe | --- native_write_msr_safe intel_pmu_enable_all x86_pmu_enable perf_pmu_enable perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule | |--87.24%-- read_events | sys_io_getevents | system_call_fastpath | 0x7fa3f9a59644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | |--12.74%-- futex_wait_queue_me | futex_wait | do_futex | sys_futex | system_call_fastpath | pthread_cond_timedwait@@GLIBC_2.3.2 | os_event::wait_time_low(unsigned long, long) | | | |--99.71%-- srv_monitor_thread | | start_thread | --0.29%-- [...] --0.01%-- [...] 0.11% mysqld [kernel.kallsyms] [k] finish_task_switch | --- finish_task_switch __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) | |--61.21%-- srv_error_monitor_thread | start_thread | --38.79%-- dict_stats_thread start_thread 0.10% mysqld [kernel.kallsyms] [k] perf_pmu_enable | --- perf_pmu_enable | |--50.21%-- __perf_event_task_sched_in | finish_task_switch | __schedule | schedule | read_events | sys_io_getevents | system_call_fastpath | 0x7fa3f9a59644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | --49.79%-- perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fa3f9a59644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.07% mysqld [kernel.kallsyms] [k] hrtimer_try_to_cancel | --- hrtimer_try_to_cancel hrtimer_nanosleep sys_nanosleep system_call_fastpath 0x7fa3f9c6999d srv_master_thread start_thread 0.04% mysqld [kernel.kallsyms] [k] __perf_event_task_sched_in | --- __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fa3f9a59644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.03% mysqld [kernel.kallsyms] [k] intel_pmu_enable_all | --- intel_pmu_enable_all x86_pmu_enable perf_pmu_enable perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule schedule_hrtimeout_range_clock schedule_hrtimeout_range poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath 0x7fa3f871700d vio_socket_io_wait vio_read net_read_raw_loop(st_net*, unsigned long) net_read_packet(st_net*, unsigned long*) my_net_read Protocol_classic::read_packet() Protocol_classic::get_command(COM_DATA*, enum_server_command*) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.02% mysqld [kernel.kallsyms] [k] perf_ctx_unlock | --- perf_ctx_unlock __perf_event_task_sched_in finish_task_switch __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) ib_wqueue_timedwait(ib_wqueue_t*, long) fts_optimize_thread(void*) start_thread # # (For a higher level overview, try: perf report --sort comm,dso) # -- 5.7.22 mysql> pager grep non-sence PAGER set to 'grep non-sence' mysql> select * from geodata; 1 row in set (52.37 sec) mysql> select * from geodata; 1 row in set (52.34 sec) mysql> select json_col from geodata; 1 row in set (52.34 sec) mysql> - * perf report -i mysql-5_7.22.g.perf|c++filt # ======== # captured on: Fri Feb 28 11:41:35 2020 # hostname : hod03 # os release : 3.8.13-98.2.2.el7uek.x86_64 # perf version : 3.8.13-98.2.2.el7uek.x86_64 # arch : x86_64 # nrcpus online : 32 # nrcpus avail : 32 # cpudesc : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz # cpuid : GenuineIntel,6,62,4 # total memory : 264098836 kB # cmdline : /usr/libexec/perf.3.8.13-98.2.2.el7uek.x86_64 record -g -F 10 -o mysql-5_7.22.g.perf -p 15793 -- sleep 20 # event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, id = { 229, 230, 231, 232, 233, 234, 235, 236, 237, 238, 239, 240, 241, 242, 243, 244, 245, 246, 247, 248, 249, 250, 251, 252, 253, 254, 255, 256 } # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5 # ======== # # Samples: 253 of event 'cycles' # Event count (approx.): 59637611695 # # Overhead Command Shared Object Symbol # ........ ....... ................. ................................. # 98.10% mysqld libc-2.17.so [.] __memmove_ssse3_back | --- __memmove_ssse3_back | |--77.96%-- String::mem_realloc(unsigned long, bool) | wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) | wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) | wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) | wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) | wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) | wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) | wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) | Field_json::val_str(String*, String*) | Field::send_text(Protocol*) | THD::send_result_set_row(List*) | Query_result_send::send_data(List&) | end_send(JOIN*, QEP_TAB*, bool) | evaluate_join_record(JOIN*, QEP_TAB*) | sub_select(JOIN*, QEP_TAB*, bool) | JOIN::exec() | handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) | execute_sqlcom_select(THD*, TABLE_LIST*) | mysql_execute_command(THD*, bool) | mysql_parse(THD*, Parser_state*) | dispatch_command(THD*, COM_DATA const*, enum_server_command) | do_command(THD*) | handle_connection | pfs_spawn_thread | start_thread | --22.04%-- btr_copy_externally_stored_field(unsigned long*, unsigned char const*, page_size_t const&, unsigned long, mem_block_info_t*) row_sel_store_mysql_field_func(unsigned char*, row_prebuilt_t*, unsigned char const*, unsigned long const*, unsigned long, mysql_row_templ_t const*, unsigned long) row_sel_store_mysql_rec(unsigned char*, row_prebuilt_t*, unsigned char const*, dtuple_t const*, unsigned long, dict_index_t const*, unsigned long const*, bool) row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) ha_innobase::index_first(unsigned char*) ha_innobase::rnd_next(unsigned char*) handler::ha_rnd_next(unsigned char*) rr_sequential(READ_RECORD*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.43% mysqld [kernel.kallsyms] [k] apic_timer_interrupt | --- apic_timer_interrupt __memmove_ssse3_back String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.43% mysqld mysqld [.] String::mem_realloc(unsigned long, bool) | --- String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.43% mysqld mysqld [.] dtoa.clone.0 | --- dtoa.clone.0 my_gcvt wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.43% mysqld [kernel.kallsyms] [k] trigger_load_balance | --- trigger_load_balance scheduler_tick update_process_times tick_sched_handle.isra.12 tick_sched_timer __run_hrtimer hrtimer_interrupt smp_apic_timer_interrupt apic_timer_interrupt __memmove_ssse3_back String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.05% mysqld [kernel.kallsyms] [k] finish_task_switch | --- finish_task_switch __schedule schedule | |--72.58%-- read_events | sys_io_getevents | system_call_fastpath | 0x7f7f13a56644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | --27.42%-- futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) srv_monitor_thread start_thread 0.04% mysqld [kernel.kallsyms] [k] native_write_msr_safe | --- native_write_msr_safe intel_pmu_enable_all x86_pmu_enable perf_pmu_enable perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule | |--68.20%-- read_events | sys_io_getevents | system_call_fastpath | 0x7f7f13a56644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | |--31.79%-- futex_wait_queue_me | futex_wait | do_futex | sys_futex | system_call_fastpath | pthread_cond_timedwait@@GLIBC_2.3.2 | os_event::wait_time_low(unsigned long, long) | | | |--68.48%-- srv_error_monitor_thread | | start_thread | | | |--31.44%-- buf_flush_page_cleaner_coordinator | | start_thread | --0.09%-- [...] --0.01%-- [...] 0.02% mysqld [kernel.kallsyms] [k] __schedule | --- __schedule schedule | |--60.09%-- do_nanosleep | hrtimer_nanosleep | sys_nanosleep | system_call_fastpath | 0x7f7f13c6699d | srv_master_thread | start_thread | --39.91%-- read_events sys_io_getevents system_call_fastpath 0x7f7f13a56644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.02% mysqld [kernel.kallsyms] [k] perf_pmu_rotate_start.isra.41 | --- perf_pmu_rotate_start.isra.41 | |--53.35%-- __perf_event_task_sched_in | finish_task_switch | __schedule | schedule | futex_wait_queue_me | futex_wait | do_futex | sys_futex | system_call_fastpath | pthread_cond_timedwait@@GLIBC_2.3.2 | os_event::wait_time_low(unsigned long, long) | lock_wait_timeout_thread | start_thread | --46.65%-- perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7f7f13a56644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.02% mysqld [kernel.kallsyms] [k] __perf_event_task_sched_in | --- __perf_event_task_sched_in finish_task_switch __schedule schedule | |--61.98%-- futex_wait_queue_me | futex_wait | do_futex | sys_futex | system_call_fastpath | pthread_cond_timedwait@@GLIBC_2.3.2 | os_event::wait_time_low(unsigned long, long) | dict_stats_thread | start_thread | --38.02%-- schedule_hrtimeout_range_clock schedule_hrtimeout_range poll_schedule_timeout do_sys_poll sys_poll system_call_fastpath 0x7f7f1271400d vio_socket_io_wait vio_read net_read_raw_loop(st_net*, unsigned long) net_read_packet(st_net*, unsigned long*) my_net_read Protocol_classic::read_packet() Protocol_classic::get_command(COM_DATA*, enum_server_command*) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.01% mysqld [kernel.kallsyms] [k] __ticket_spin_unlock | --- __ticket_spin_unlock __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) ib_wqueue_timedwait(ib_wqueue_t*, long) fts_optimize_thread(void*) start_thread # # (For a higher level overview, try: perf report --sort comm,dso) # - json col perf report -i mysql-5_7.22__.g.perf|c++filt # ======== # captured on: Fri Feb 28 11:44:20 2020 # hostname : hod03 # os release : 3.8.13-98.2.2.el7uek.x86_64 # perf version : 3.8.13-98.2.2.el7uek.x86_64 # arch : x86_64 # nrcpus online : 32 # nrcpus avail : 32 # cpudesc : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz # cpuid : GenuineIntel,6,62,4 # total memory : 264098836 kB # cmdline : /usr/libexec/perf.3.8.13-98.2.2.el7uek.x86_64 record -g -F 10 -o mysql-5_7.22__.g.perf -p 15793 -- sleep 20 # event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, id = { 285, 286, 287, 288, 289, 290, 291, 292, 293, 294, 295, 296, 297, 298, 299, 300, 301, 302, 303, 304, 305, 306, 307, 308, 309, 310, 311, 312 } # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5 # ======== # # Samples: 249 of event 'cycles' # Event count (approx.): 56885424923 # # Overhead Command Shared Object Symbol # ........ ....... ................. ................................. # 78.35% mysqld libc-2.17.so [.] __memmove_ssse3_back | --- __memmove_ssse3_back String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 19.66% mysqld mysqld [.] pow5mult | --- pow5mult dtoa.clone.0 my_gcvt wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.46% mysqld mysqld [.] pfs_memory_alloc_v1 | --- pfs_memory_alloc_v1 my_malloc my_realloc String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.46% mysqld [kernel.kallsyms] [k] run_timer_softirq | --- run_timer_softirq __do_softirq call_softirq do_softirq irq_exit smp_apic_timer_interrupt apic_timer_interrupt __memmove_ssse3_back String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.46% mysqld mysqld [.] String::append(char const*, unsigned long) | --- String::append(char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.46% mysqld mysqld [.] Json_wrapper::type() const | --- Json_wrapper::type() const wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.05% mysqld [kernel.kallsyms] [k] native_write_msr_safe | --- native_write_msr_safe intel_pmu_enable_all x86_pmu_enable perf_pmu_enable perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule | |--60.47%-- read_events | sys_io_getevents | system_call_fastpath | 0x7f7f13a56644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | |--39.52%-- futex_wait_queue_me | futex_wait | do_futex | sys_futex | system_call_fastpath | pthread_cond_timedwait@@GLIBC_2.3.2 | os_event::wait_time_low(unsigned long, long) | | | |--53.37%-- lock_wait_timeout_thread | | start_thread | | | |--46.58%-- dict_stats_thread | | start_thread | --0.05%-- [...] --0.01%-- [...] 0.04% mysqld [kernel.kallsyms] [k] perf_pmu_rotate_start.isra.41 | --- perf_pmu_rotate_start.isra.41 | |--72.76%-- perf_event_context_sched_in | __perf_event_task_sched_in | finish_task_switch | __schedule | schedule | | | |--42.59%-- futex_wait_queue_me | | futex_wait | | do_futex | | sys_futex | | system_call_fastpath | | pthread_cond_timedwait@@GLIBC_2.3.2 | | os_event::wait_time_low(unsigned long, long) | | buf_flush_page_cleaner_coordinator | | start_thread | | | |--29.86%-- read_events | | sys_io_getevents | | system_call_fastpath | | 0x7f7f13a56644 | | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | | fil_aio_wait(unsigned long) | | io_handler_thread | | start_thread | | | --27.55%-- schedule_hrtimeout_range_clock | schedule_hrtimeout_range | poll_schedule_timeout | do_sys_poll | sys_poll | system_call_fastpath | 0x7f7f1271400d | vio_socket_io_wait | vio_read | net_read_raw_loop(st_net*, unsigned long) | net_read_packet(st_net*, unsigned long*) | my_net_read | Protocol_classic::read_packet() | Protocol_classic::get_command(COM_DATA*, enum_server_command*) | do_command(THD*) | handle_connection | pfs_spawn_thread | start_thread | --27.24%-- __perf_event_task_sched_in finish_task_switch __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) ib_wqueue_timedwait(ib_wqueue_t*, long) fts_optimize_thread(void*) start_thread 0.03% mysqld [kernel.kallsyms] [k] finish_task_switch | --- finish_task_switch __schedule schedule | |--54.35%-- do_nanosleep | hrtimer_nanosleep | sys_nanosleep | system_call_fastpath | 0x7f7f13c6699d | srv_master_thread | start_thread | --45.65%-- read_events sys_io_getevents system_call_fastpath 0x7f7f13a56644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.02% mysqld [kernel.kallsyms] [k] futex_wait | --- futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) srv_error_monitor_thread start_thread 0.01% mysqld [kernel.kallsyms] [k] __ticket_spin_unlock | --- __ticket_spin_unlock finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7f7f13a56644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.01% mysqld [kernel.kallsyms] [k] perf_pmu_enable | --- perf_pmu_enable __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7f7f13a56644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.01% mysqld [kernel.kallsyms] [k] intel_pmu_enable_all | --- intel_pmu_enable_all x86_pmu_enable perf_pmu_enable perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) srv_monitor_thread start_thread # # (For a higher level overview, try: perf report --sort comm,dso) # -- 5.7.29 - * columns perf report -i mysql-5_7.29.g.perf|c++filt # ======== # captured on: Fri Feb 28 12:00:27 2020 # hostname : hod03 # os release : 3.8.13-98.2.2.el7uek.x86_64 # perf version : 3.8.13-98.2.2.el7uek.x86_64 # arch : x86_64 # nrcpus online : 32 # nrcpus avail : 32 # cpudesc : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz # cpuid : GenuineIntel,6,62,4 # total memory : 264098836 kB # cmdline : /usr/libexec/perf.3.8.13-98.2.2.el7uek.x86_64 record -g -F 10 -o mysql-5_7.29.g.perf -p 17481 -- sleep 20 # event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, id = { 313, 314, 315, 316, 317, 318, 319, 320, 321, 322, 323, 324, 325, 326, 327, 328, 329, 330, 331, 332, 333, 334, 335, 336, 337, 338, 339, 340 } # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5 # ======== # # Samples: 271 of event 'cycles' # Event count (approx.): 55596051480 # # Overhead Command Shared Object Symbol # ........ ....... ................. ......................................... # 98.39% mysqld libc-2.17.so [.] __memmove_ssse3_back | --- __memmove_ssse3_back String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.47% mysqld mysqld [.] json_binary::parse_scalar(unsigned char, char const*, unsigned long) | --- json_binary::parse_scalar(unsigned char, char const*, unsigned long) json_binary::Value::element(unsigned long) const Json_wrapper::operator[](unsigned long) const wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.47% mysqld mysqld [.] dtoa.clone.0 | --- dtoa.clone.0 my_gcvt wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.47% mysqld [kernel.kallsyms] [k] acct_update_integrals | --- acct_update_integrals account_user_time account_process_tick update_process_times tick_sched_handle.isra.12 tick_sched_timer __run_hrtimer hrtimer_interrupt smp_apic_timer_interrupt apic_timer_interrupt __memmove_ssse3_back String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.05% mysqld [kernel.kallsyms] [k] finish_task_switch | --- finish_task_switch __schedule schedule | |--74.54%-- read_events | sys_io_getevents | system_call_fastpath | 0x7fd831da9644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | --25.46%-- futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) ib_wqueue_timedwait(ib_wqueue_t*, long) fts_optimize_thread(void*) start_thread 0.04% mysqld [kernel.kallsyms] [k] __ticket_spin_unlock | --- __ticket_spin_unlock | |--37.99%-- finish_task_switch | __schedule | schedule | read_events | sys_io_getevents | system_call_fastpath | 0x7fd831da9644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | |--31.47%-- perf_ctx_unlock | perf_event_context_sched_in | __perf_event_task_sched_in | finish_task_switch | __schedule | schedule | read_events | sys_io_getevents | system_call_fastpath | 0x7fd831da9644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | --30.54%-- perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fd831da9644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.03% mysqld [kernel.kallsyms] [k] native_write_msr_safe | --- native_write_msr_safe intel_pmu_enable_all x86_pmu_enable perf_pmu_enable | |--87.98%-- perf_event_context_sched_in | __perf_event_task_sched_in | finish_task_switch | __schedule | schedule | | | |--76.68%-- read_events | | sys_io_getevents | | system_call_fastpath | | 0x7fd831da9644 | | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | | fil_aio_wait(unsigned long) | | io_handler_thread | | start_thread | | | |--23.30%-- futex_wait_queue_me | | futex_wait | | do_futex | | sys_futex | | system_call_fastpath | | pthread_cond_timedwait@@GLIBC_2.3.2 | | os_event::wait_time_low(unsigned long, long) | | | | | |--99.71%-- lock_wait_timeout_thread | | | start_thread | | --0.29%-- [...] | --0.01%-- [...] | --12.02%-- x86_pmu_commit_txn group_sched_in __perf_event_enable remote_function generic_smp_call_function_single_interrupt smp_call_function_single_interrupt call_function_single_interrupt __memmove_ssse3_back String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.03% mysqld [kernel.kallsyms] [k] __schedule | --- __schedule schedule | |--53.75%-- futex_wait_queue_me | futex_wait | do_futex | sys_futex | system_call_fastpath | pthread_cond_timedwait@@GLIBC_2.3.2 | os_event::wait_time_low(unsigned long, long) | buf_flush_page_cleaner_coordinator | start_thread | --46.25%-- read_events sys_io_getevents system_call_fastpath 0x7fd831da9644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.02% mysqld [kernel.kallsyms] [k] futex_wait | --- futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) srv_error_monitor_thread start_thread 0.02% mysqld [kernel.kallsyms] [k] futex_wait_queue_me | --- futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) dict_stats_thread start_thread 0.02% mysqld [kernel.kallsyms] [k] do_nanosleep | --- do_nanosleep hrtimer_nanosleep sys_nanosleep system_call_fastpath 0x7fd8321bd99d srv_master_thread start_thread 0.01% mysqld [kernel.kallsyms] [k] perf_pmu_enable | --- perf_pmu_enable perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fd831da9644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.01% mysqld [kernel.kallsyms] [k] perf_pmu_rotate_start.isra.41 | --- perf_pmu_rotate_start.isra.41 perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) srv_monitor_thread start_thread # # (For a higher level overview, try: perf report --sort comm,dso) # - JSON colum perf report -i mysql-5_7.29_.g.perf|c++filt # ======== # captured on: Fri Feb 28 12:02:23 2020 # hostname : hod03 # os release : 3.8.13-98.2.2.el7uek.x86_64 # perf version : 3.8.13-98.2.2.el7uek.x86_64 # arch : x86_64 # nrcpus online : 32 # nrcpus avail : 32 # cpudesc : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz # cpuid : GenuineIntel,6,62,4 # total memory : 264098836 kB # cmdline : /usr/libexec/perf.3.8.13-98.2.2.el7uek.x86_64 record -g -F 10 -o mysql-5_7.29_.g.perf -p 17481 -- sleep 20 # event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, id = { 341, 342, 343, 344, 345, 346, 347, 348, 349, 350, 351, 352, 353, 354, 355, 356, 357, 358, 359, 360, 361, 362, 363, 364, 365, 366, 367, 368 } # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5 # ======== # # Samples: 271 of event 'cycles' # Event count (approx.): 55020662200 # # Overhead Command Shared Object Symbol # ........ ....... ................. ................................. # 98.87% mysqld libc-2.17.so [.] __memmove_ssse3_back | --- __memmove_ssse3_back String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.47% mysqld [kernel.kallsyms] [k] __ticket_spin_lock | --- __ticket_spin_lock _raw_spin_lock update_wall_time do_timer tick_do_update_jiffies64 tick_sched_do_timer tick_sched_timer __run_hrtimer hrtimer_interrupt smp_apic_timer_interrupt apic_timer_interrupt __memmove_ssse3_back String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.47% mysqld libc-2.17.so [.] _int_free | --- _int_free (nil) (nil) 0.05% mysqld [kernel.kallsyms] [k] native_write_msr_safe | --- native_write_msr_safe intel_pmu_enable_all x86_pmu_enable perf_pmu_enable | |--94.18%-- perf_event_context_sched_in | __perf_event_task_sched_in | finish_task_switch | __schedule | schedule | | | |--62.15%-- futex_wait_queue_me | | futex_wait | | do_futex | | sys_futex | | system_call_fastpath | | pthread_cond_timedwait@@GLIBC_2.3.2 | | os_event::wait_time_low(unsigned long, long) | | | | | |--49.96%-- buf_flush_page_cleaner_coordinator | | | start_thread | | | | | |--27.76%-- srv_error_monitor_thread | | | start_thread | | | | | |--22.25%-- lock_wait_timeout_thread | | | start_thread | | --0.03%-- [...] | | | |--37.85%-- read_events | | sys_io_getevents | | system_call_fastpath | | 0x7fd831da9644 | | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | | fil_aio_wait(unsigned long) | | io_handler_thread | | start_thread | --0.01%-- [...] | --5.82%-- x86_pmu_commit_txn group_sched_in __perf_event_enable remote_function generic_smp_call_function_single_interrupt smp_call_function_single_interrupt call_function_single_interrupt __memmove_ssse3_back String::mem_realloc(unsigned long, bool) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) wrapper_to_string(Json_wrapper const&, String*, bool, bool, char const*, unsigned long) Field_json::val_str(String*, String*) Field::send_text(Protocol*) THD::send_result_set_row(List*) Query_result_send::send_data(List&) end_send(JOIN*, QEP_TAB*, bool) evaluate_join_record(JOIN*, QEP_TAB*) sub_select(JOIN*, QEP_TAB*, bool) JOIN::exec() handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long) execute_sqlcom_select(THD*, TABLE_LIST*) mysql_execute_command(THD*, bool) mysql_parse(THD*, Parser_state*) dispatch_command(THD*, COM_DATA const*, enum_server_command) do_command(THD*) handle_connection pfs_spawn_thread start_thread 0.03% mysqld [kernel.kallsyms] [k] finish_task_switch | --- finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fd831da9644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.03% mysqld [kernel.kallsyms] [k] __schedule | --- __schedule schedule | |--50.39%-- futex_wait_queue_me | futex_wait | do_futex | sys_futex | system_call_fastpath | pthread_cond_timedwait@@GLIBC_2.3.2 | os_event::wait_time_low(unsigned long, long) | ib_wqueue_timedwait(ib_wqueue_t*, long) | fts_optimize_thread(void*) | start_thread | --49.61%-- read_events sys_io_getevents system_call_fastpath 0x7fd831da9644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.03% mysqld [kernel.kallsyms] [k] __ticket_spin_unlock | --- __ticket_spin_unlock | |--53.33%-- finish_task_switch | __schedule | schedule | read_events | sys_io_getevents | system_call_fastpath | 0x7fd831da9644 | LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) | os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) | fil_aio_wait(unsigned long) | io_handler_thread | start_thread | --46.67%-- perf_ctx_unlock perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fd831da9644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.02% mysqld [kernel.kallsyms] [k] do_nanosleep | --- do_nanosleep hrtimer_nanosleep sys_nanosleep system_call_fastpath 0x7fd8321bd99d srv_master_thread start_thread 0.01% mysqld [kernel.kallsyms] [k] futex_wait_queue_me | --- futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) srv_monitor_thread start_thread 0.01% mysqld [kernel.kallsyms] [k] perf_event_context_sched_in | --- perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule futex_wait_queue_me futex_wait do_futex sys_futex system_call_fastpath pthread_cond_timedwait@@GLIBC_2.3.2 os_event::wait_time_low(unsigned long, long) dict_stats_thread start_thread 0.01% mysqld [kernel.kallsyms] [k] perf_pmu_rotate_start.isra.41 | --- perf_pmu_rotate_start.isra.41 perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fd831da9644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread 0.00% mysqld [kernel.kallsyms] [k] perf_ctx_unlock | --- perf_ctx_unlock perf_event_context_sched_in __perf_event_task_sched_in finish_task_switch __schedule schedule read_events sys_io_getevents system_call_fastpath 0x7fd831da9644 LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*) os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*) fil_aio_wait(unsigned long) io_handler_thread start_thread # # (