You are viewing kristiannielsen

Kristian Nielsen - More on 40% better single-threaded performance in MariaDB
January 23rd, 2014
11:44 am

[Link]

Previous Entry Add to Memories Share Next Entry
More on 40% better single-threaded performance in MariaDB

In my previous post I wrote about how I achived a >40% speedup on sysbench read-only using profile-guided optimisation (PGO). While this is a preliminary result, I though it was so interesting that it deserved early mention. The fact that any benchmark can be improved that much shows clearly that PGO is something worth looking into. Even if we will probably not improve all workloads by 40%, it seems highly likely that we can obtain significant gains also for many real workloads.

I had one or two interesting comments on the post that raise valid concerns, so I wanted to write a follow-up here, explaining some of the points in more details and going deeper into the performance counter measurements. As I wrote before, actual observations and measurements are crucial to fully understand performance of complex code on modern CPUs. Intuition and guesswork just does not suffice.

On branch mispredictions

bludwarf suggested that branch mispredictions could be an important part of the picture:

> It would be interesting to see the hottest spots.... Having to execute just
> a lot of code is not an explanation. If it would be so, then profiler
> feedback won't affect performance so much. I believe the reson for so big
> difference for the results is branch misprediction.
I had similar thoughts when I first saw the results, but I was able to verify my explanation with actual measurements of instructions retired and icache misses before and after profile-guided optimisations:
    171821  INST_RETIRED.ANY
     17730  ICACHE.MISSES

    166686  INST_RETIRED.ANY
     13643  ICACHE.MISSES

Before PGO, ICACHE.MISSES/INST_RETIRED.ANY = 10.3%. After, we get 8.2%. So we do get significant less icache misses. I wrote in my previous post some plausible reasons for that with my remarks on basic blocks, though I have not tried to verify those with actual measurements.

I also checked branch mispredictions. The Intel manual has two measures to estimate the cost of branch misprediction. One is time wasted due to speculatively issued uops that do not retire, %Bad_Speculation = (UOPS_ISSUED.ANY - UOPS_RETIRED.RETIRE_SLOTS + 4 * INT_MISC.RECOVERY_CYCLES ) / (4*CPU_CLK_UNHALTED.THREAD). The other is cycles wasted based on an estimated cost of 20 cycles per misprediction, %BR.MISP.COST = 20 * BR_MISP_RETIRED.ALL_BRANCHES_PS / CPU_CLK_UNHALTED.THREAD. Here are the relevant measurements taken before and after (two sets of measurements, as Sandy Bridge supports only 4 simultaneous performance counters):

    486641  CPU_CLK_UNHALTED.THREAD
    205880  UOPS_RETIRED.RETIRE_SLOTS
    226184  UOPS_ISSUED.ANY
      7219  INT_MISC.RECOVERY_CYCLES
    %Bad_Speculation = 2.5%

    335051  CPU_CLK_UNHALTED.THREAD
    194616  UOPS_RETIRED.RETIRE_SLOTS
    216353  UOPS_ISSUED.ANY
      6830  INT_MISC.RECOVERY_CYCLES
    %Bad_Speculation = 3.7%

    490250  CPU_CLK_UNHALTED.THREAD
      1310  BR_MISP_RETIRED.ALL_BRANCHES_PS
    %BR.MISP.COST = 5.3%

    338524  CPU_CLK_UNHALTED.THREAD
      1147  BR_MISP_RETIRED.ALL_BRANCHES_PS
    %BR.MISP.COST = 6.8%

Note that the actual branch misprediction is much the same. But with less time spent on other bottlenecks, the estimated relative cost becomes higher.

Most of the branch mispredictions are due to indirect branches (virtual functions and @plt entries in shared libraries). Even without PGO the CPU is able to predict other branches very well, so compiler or __builtin_expect can not help much.

At the end of this post, I have appended the top of some per-function profiles. They show how branch mispredictions are mostly from commonly called library functions like memcpy() (these are mispredictions of the indirect jumps in the PLT), and from virtual function calls. They also show how the icache misses are spread out more or less evenly, correlating strongly with the count of actual instructions executed in various parts of the code.

On better coverage of the PGO

A comment from Anonymous raised another valid concern:

> If I read you correctly, you are using the same benchmark for optimizing as
> well as measuring performance increases. You need to have different test and
> training sets or your measurements don't generalize.

This is true, of course. The sysbench read-only exercises only an extremely narrow subset of mysqld functionality. The next step, on which I am already working, is to implement a more suitable and general workload for the profile, which can hopefully cover, and hence speedup, a significant portion of common real-life workloads.

More tests will be needed to be sure that real-world gains can be achieved, but I am very hopeful. After all, much of the code of sys-bench read-only is also used in many other workloads, and much of the properties (eg. infrequency of the lots and lots of error check branches) should be similar.

My main concern is that GCC will choose to de-optimise code that is not covered by the test load, to the extent that it significantly harms performance in some cases. But it should not be too much of a problem - after all, GCC will still try to optimise the generated code as best it can, and if the information it has from the profile is incomplete, it should not be much worse than having no information, as is the case without PGO. And over time, we can extend the coverage of the test load to help eliminate any problems that do turn up.

Since the last post, I implemented a first version of a program that generates a test load. For now, I put it on github: gen_profile_load. The program generates a range of different loads, such as simple key lookups, small joins, inserts/updates/deletes, under various conditions such as with/without binlogging, with/without prepared statements, and so on.

I plan to next do some tests with using this for doing the PGO, and checking the effect on sysbench read-only and possibly other benchmarks. Another idea I had was to try to use only parts of the generated load, and test that this does not cause significant regressions on the omitted parts. This could help in getting some idea of what kind of (hopefully small) performance regressions can be expected for workloads that are not well covered by the PGO.

Detailed profiles

These are pasted from the output of perf report. They show the top functions in terms of instructions executed, icache misses suffered, and branches mispredicted.

Instructions retired (INST_RETIRED.ANY), before PGO:

Samples: 171K of event 'rc0', Event count (approx.): 171821
  1,94%  mysqld  libc-2.13.so         [.] __memcpy_ssse3
  1,92%  mysqld  mysqld               [.] my_hash_sort_bin
  1,60%  mysqld  mysqld               [.] make_join_statistics(JOIN*, List<TABLE_LIST>&, Item*, st_dynamic_array*)
  1,48%  mysqld  mysqld               [.] malloc
  1,36%  mysqld  mysqld               [.] free
  1,34%  mysqld  mysqld               [.] row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
  1,31%  mysqld  mysqld               [.] alloc_root
  1,30%  mysqld  mysqld               [.] JOIN::optimize_inner()
  1,16%  mysqld  mysqld               [.] my_malloc_size_cb_func
  1,14%  mysqld  mysqld               [.] ha_innobase::build_template(bool)
  1,08%  mysqld  mysqld               [.] cmp_dtuple_rec_with_match_low(dtuple_t const*, unsigned char const*, unsigned long const*, unsigned long, unsigned long*, unsigned long*)
  1,08%  mysqld  mysqld               [.] JOIN::save_explain_data_intern(Explain_query*, bool, bool, bool, char const*)
  1,07%  mysqld  libpthread-2.13.so   [.] __pthread_mutex_unlock_usercnt
  1,01%  mysqld  libpthread-2.13.so   [.] pthread_mutex_lock
  1,00%  mysqld  mysqld               [.] Protocol::net_store_data(unsigned char const*, unsigned long, charset_info_st const*, charset_info_st const*)
  0,98%  mysqld  libpthread-2.13.so   [.] pthread_getspecific
  0,93%  mysqld  mysqld               [.] mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_
  0,90%  mysqld  mysqld               [.] build_template_field(row_prebuilt_t*, dict_index_t*, dict_index_t*, TABLE*, Field const*, unsigned long)
  0,88%  mysqld  [vdso]               [.] 0x000000000000070c
  0,83%  mysqld  mysqld               [.] rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, unsigned long, mem_block_info_t**, char const*, unsigned long)
  0,79%  mysqld  libc-2.13.so         [.] __memset_sse2
  0,78%  mysqld  libc-2.13.so         [.] __strlen_sse42
  0,77%  mysqld  [kernel.kallsyms]    [k] unix_stream_recvmsg
  0,77%  mysqld  mysqld               [.] THD::enter_stage(PSI_stage_info_none const*, PSI_stage_info_none*, char const*, char const*, unsigned int)
  0,71%  mysqld  mysqld               [.] _ZN4JOIN7prepareEPPP4ItemP10TABLE_LISTjS1_jP8st_orderbS7_S1_S7_P13st_select_lexP18st_select_lex_unit.part.227
  0,70%  mysqld  libc-2.13.so         [.] __strcmp_sse42
  0,70%  mysqld  mysqld               [.] Protocol::send_result_set_metadata(List<Item>*, unsigned int)
  0,70%  mysqld  [kernel.kallsyms]    [k] update_cfs_shares
  0,69%  mysqld  mysqld               [.] open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)
  0,69%  mysqld  mysqld               [.] _ZL19update_ref_and_keysP3THDP16st_dynamic_arrayP13st_join_tablejP4ItemyP13st_select_lexPP17st_sargable_param.isra.231
  0,68%  mysqld  mysqld               [.] dispatch_command(enum_server_command, THD*, char*, unsigned int)
  0,60%  mysqld  mysqld               [.] create_ref_for_key(JOIN*, st_join_table*, keyuse_t*, bool, unsigned long long)
  0,59%  mysqld  [kernel.kallsyms]    [k] effective_load
  0,56%  mysqld  [kernel.kallsyms]    [k] select_task_rq_fair
  0,56%  mysqld  [kernel.kallsyms]    [k] _raw_spin_lock_irqsave
  0,50%  mysqld  mysqld               [.] ha_innobase::external_lock(THD*, int)
  0,48%  mysqld  mysqld               [.] my_malloc
  0,48%  mysqld  [kernel.kallsyms]    [k] enqueue_task_fair
  0,48%  mysqld  mysqld               [.] lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int)
  0,47%  mysqld  [kernel.kallsyms]    [k] update_entity_load_avg
  0,46%  mysqld  mysqld               [.] mysql_execute_command(THD*)
  0,46%  mysqld  mysqld               [.] btr_search_guess_on_hash(dict_index_t*, btr_search_t*, dtuple_t const*, unsigned long, unsigned long, btr_cur_t*, unsigned long, mtr_t*)
  0,45%  mysqld  mysqld               [.] Item_func::type() const
  0,44%  mysqld  [kernel.kallsyms]    [k] update_curr
  0,44%  mysqld  [kernel.kallsyms]    [k] copy_user_generic_string
  0,44%  mysqld  [kernel.kallsyms]    [k] do_raw_spin_lock
  0,43%  mysqld  mysqld               [.] my_lengthsp_8bit
  0,43%  mysqld  [kernel.kallsyms]    [k] _raw_spin_unlock_irqrestore
  0,43%  mysqld  [kernel.kallsyms]    [k] init_sync_kiocb.constprop.15
  0,41%  mysqld  mysqld               [.] get_best_combination(JOIN*)
  0,40%  mysqld  mysqld               [.] sort_and_filter_keyuse(THD*, st_dynamic_array*, bool)
  0,36%  mysqld  mysqld               [.] Item_equal::Item_equal(Item*, Item*, bool)
  0,36%  mysqld  mysqld               [.] Item::Item()
  0,35%  mysqld  [kernel.kallsyms]    [k] atomic64_dec_and_test
  0,35%  mysqld  mysqld               [.] Arg_comparator::set_cmp_func(Item_result_field*, Item**, Item**, Item_result)
  0,35%  mysqld  mysqld               [.] JOIN::exec_inner()
  0,35%  mysqld  [kernel.kallsyms]    [k] account_entity_enqueue
  0,35%  mysqld  [kernel.kallsyms]    [k] do_sys_poll
  0,35%  mysqld  [kernel.kallsyms]    [k] system_call
  0,34%  mysqld  mysqld               [.] JOIN::destroy()
  0,34%  mysqld  mysqld               [.] ha_innobase::store_lock(THD*, st_thr_lock_data**, thr_lock_type)

Icache misses (ICACHE.MISSES), before PGO:

Samples: 17K of event 'r280', Event count (approx.): 17730
  2,21%  mysqld  mysqld               [.] JOIN::optimize_inner()
  2,04%  mysqld  mysqld               [.] row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
  1,91%  mysqld  mysqld               [.] make_join_statistics(JOIN*, List<TABLE_LIST>&, Item*, st_dynamic_array*)
  1,42%  mysqld  mysqld               [.] JOIN::save_explain_data_intern(Explain_query*, bool, bool, bool, char const*)
  1,27%  mysqld  libc-2.13.so         [.] __memcpy_ssse3
  1,20%  mysqld  mysqld               [.] malloc
  1,09%  mysqld  mysqld               [.] mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_
  1,07%  mysqld  mysqld               [.] open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)
  0,90%  mysqld  mysqld               [.] create_ref_for_key(JOIN*, st_join_table*, keyuse_t*, bool, unsigned long long)
  0,90%  mysqld  [vdso]               [.] 0x0000000000000771
  0,86%  mysqld  libpthread-2.13.so   [.] pthread_mutex_lock
  0,83%  mysqld  mysqld               [.] _ZN4JOIN7prepareEPPP4ItemP10TABLE_LISTjS1_jP8st_orderbS7_S1_S7_P13st_select_lexP18st_select_lex_unit.part.227
  0,73%  mysqld  mysqld               [.] mysql_execute_command(THD*)
  0,72%  mysqld  mysqld               [.] alloc_root
  0,68%  mysqld  mysqld               [.] JOIN::exec_inner()
  0,65%  mysqld  libc-2.13.so         [.] __memset_sse2
  0,64%  mysqld  mysqld               [.] JOIN::destroy()
  0,63%  mysqld  mysqld               [.] free
  0,59%  mysqld  [kernel.kallsyms]    [k] _raw_spin_lock_irqsave
  0,55%  mysqld  mysqld               [.] _ZL19update_ref_and_keysP3THDP16st_dynamic_arrayP13st_join_tablejP4ItemyP13st_select_lexPP17st_sargable_param.isra.231
  0,55%  mysqld  [kernel.kallsyms]    [k] do_raw_spin_lock
  0,54%  mysqld  mysqld               [.] dispatch_command(enum_server_command, THD*, char*, unsigned int)
  0,54%  mysqld  mysqld               [.] ha_innobase::external_lock(THD*, int)
  0,52%  mysqld  mysqld               [.] THD::enter_stage(PSI_stage_info_none const*, PSI_stage_info_none*, char const*, char const*, unsigned int)
  0,51%  mysqld  mysqld               [.] my_malloc_size_cb_func
  0,51%  mysqld  mysqld               [.] Protocol::send_result_set_metadata(List<Item>*, unsigned int)
  0,51%  mysqld  mysqld               [.] btr_search_guess_on_hash(dict_index_t*, btr_search_t*, dtuple_t const*, unsigned long, unsigned long, btr_cur_t*, unsigned long, mtr_t*)
  0,50%  mysqld  mysqld               [.] ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function)
  0,47%  mysqld  mysqld               [.] setup_conds(THD*, TABLE_LIST*, List<TABLE_LIST>&, Item**)
  0,47%  mysqld  mysqld               [.] get_best_combination(JOIN*)
  0,47%  mysqld  mysqld               [.] ha_innobase::store_lock(THD*, st_thr_lock_data**, thr_lock_type)
  0,47%  mysqld  libc-2.13.so         [.] __strcmp_sse42
  0,47%  mysqld  [kernel.kallsyms]    [k] unix_stream_recvmsg
  0,46%  mysqld  mysqld               [.] trx_commit(trx_t*)
  0,44%  mysqld  [kernel.kallsyms]    [k] fget_light
  0,43%  mysqld  mysqld               [.] sort_and_filter_keyuse(THD*, st_dynamic_array*, bool)
  0,43%  mysqld  [kernel.kallsyms]    [k] system_call
  0,42%  mysqld  mysqld               [.] JOIN::cleanup(bool)
  0,41%  mysqld  mysqld               [.] handle_select(THD*, LEX*, select_result*, unsigned long)
  0,41%  mysqld  mysqld               [.] mtr_commit(mtr_t*)
  0,41%  mysqld  mysqld               [.] cmp_dtuple_rec_with_match_low(dtuple_t const*, unsigned char const*, unsigned long const*, unsigned long, unsigned long*, unsigned long*)
  0,41%  mysqld  mysqld               [.] my_hash_sort_bin
  0,40%  mysqld  mysqld               [.] open_table(THD*, TABLE_LIST*, st_mem_root*, Open_table_context*)
  0,40%  mysqld  libpthread-2.13.so   [.] pthread_getspecific
  0,39%  mysqld  mysqld               [.] buf_page_get_known_nowait(unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*)
  0,39%  mysqld  libpthread-2.13.so   [.] __pthread_mutex_unlock_usercnt
  0,38%  mysqld  mysqld               [.] _ZL21join_read_const_tableP13st_join_tableP11st_position.isra.226
  0,38%  mysqld  mysqld               [.] lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int)
  0,38%  mysqld  mysqld               [.] find_field_in_table(THD*, TABLE*, char const*, unsigned int, bool, unsigned int*)
  0,37%  mysqld  mysqld               [.] ha_innobase::extra(ha_extra_function)
  0,37%  mysqld  mysqld               [.] ha_innobase::build_template(bool)
  0,37%  mysqld  [kernel.kallsyms]    [k] enqueue_task_fair
  0,36%  mysqld  mysqld               [.] add_key_field(JOIN*, key_field_t**, unsigned int, Item_func*, Field*, bool, Item**, unsigned int, unsigned long long, st_sargable_param**)
  0,36%  mysqld  mysqld               [.] add_key_fields(JOIN*, key_field_t**, unsigned int*, Item*, unsigned long long, st_sargable_param**)
  0,35%  mysqld  [kernel.kallsyms]    [k] update_rq_clock
  0,34%  mysqld  mysqld               [.] do_select(JOIN*, List<Item>*, TABLE*, Procedure*)
  0,33%  mysqld  mysqld               [.] my_real_read(st_net*, unsigned long*)
  0,33%  mysqld  mysqld               [.] Arg_comparator::set_cmp_func(Item_result_field*, Item**, Item**, Item_result)
  0,33%  mysqld  [kernel.kallsyms]    [k] __schedule
  0,33%  mysqld  mysqld               [.] Item::Item()
  0,32%  mysqld  mysqld               [.] thd_ha_data

Branch mispredictions (BR_MISP_RETIRED.ALL_BRANCHES_PS), before PGO:

Samples: 1K of event 'rc5:p', Event count (approx.): 1310
  7,02%  mysqld  libc-2.13.so         [.] __memcpy_ssse3
  6,64%  mysqld  libpthread-2.13.so   [.] pthread_getspecific
  3,74%  mysqld  libpthread-2.13.so   [.] pthread_mutex_unlock
  3,66%  mysqld  mysqld               [.] Item_func::type() const
  3,05%  mysqld  libc-2.13.so         [.] __memset_sse2
  2,67%  mysqld  mysqld               [.] Field_long::type() const
  2,60%  mysqld  libpthread-2.13.so   [.] pthread_mutex_lock
  2,52%  mysqld  libc-2.13.so         [.] __strcmp_sse42
  2,06%  mysqld  mysqld               [.] Item_field::used_tables() const
  2,06%  mysqld  mysqld               [.] Item_param::used_tables() const
  2,06%  mysqld  libc-2.13.so         [.] __strlen_sse42
  1,76%  mysqld  librt-2.13.so        [.] clock_gettime
  1,68%  mysqld  mysqld               [.] Item::cmp_type() const
  1,60%  mysqld  mysqld               [.] st_select_lex::master_unit()
  1,37%  mysqld  mysqld               [.] Item_equal::functype() const
  1,30%  mysqld  mysqld               [.] Item::const_item() const
  1,30%  mysqld  mysqld               [.] Item::real_item()
  1,07%  mysqld  mysqld               [.] Field_str::charset() const
  0,92%  mysqld  mysqld               [.] Protocol::end_statement()
  0,92%  mysqld  mysqld               [.] Item_field::type() const
  0,84%  mysqld  mysqld               [.] mysql_execute_command(THD*)
  0,84%  mysqld  mysqld               [.] Item_field::cleanup()
  0,84%  mysqld  mysqld               [.] Item_field::field_type() const
  0,84%  mysqld  mysqld               [.] ha_innobase::extra(ha_extra_function)
  0,84%  mysqld  libpthread-2.13.so   [.] __libc_recv
  0,76%  mysqld  mysqld               [.] Item_param::save_in_field(Field*, bool)
  0,76%  mysqld  mysqld               [.] my_hash_sort_bin
  0,69%  mysqld  mysqld               [.] make_join_statistics(JOIN*, List<TABLE_LIST>&, Item*, st_dynamic_array*)
  0,69%  mysqld  mysqld               [.] my_real_read(st_net*, unsigned long*)
  0,69%  mysqld  mysqld               [.] scheduler_wait_net_end
  0,69%  mysqld  mysqld               [.] Item_param::val_int()
  0,69%  mysqld  mysqld               [.] Item::check_cols(unsigned int)
  0,69%  mysqld  mysqld               [.] Item_field::result_type() const
  0,61%  mysqld  mysqld               [.] Field_long::pack_length() const
  0,61%  mysqld  mysqld               [.] vio_read
  0,61%  mysqld  [kernel.kallsyms]    [k] system_call
  0,53%  mysqld  mysqld               [.] Item::is_expensive()
  0,53%  mysqld  mysqld               [.] st_select_lex::outer_select()
  0,53%  mysqld  mysqld               [.] do_handle_one_connection(THD*)
  0,53%  mysqld  mysqld               [.] Explain_select::~Explain_select()
  0,53%  mysqld  mysqld               [.] Field_num::result_type() const
  0,53%  mysqld  mysqld               [.] Item_param::result_type() const
  0,53%  mysqld  mysqld               [.] Item_param::field_type() const
  0,53%  mysqld  mysqld               [.] Item_equal::count_sargable_conds(unsigned char*)
  0,53%  mysqld  mysqld               [.] Item_func_eq::functype() const
  0,53%  mysqld  mysqld               [.] ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function)
  0,53%  mysqld  [kernel.kallsyms]    [k] __pollwait
  0,53%  mysqld  [kernel.kallsyms]    [k] sock_def_readable
  0,46%  mysqld  mysqld               [.] net_before_header_psi(st_net*, void*, unsigned long)
  0,46%  mysqld  mysqld               [.] dispatch_command(enum_server_command, THD*, char*, unsigned int)
  0,46%  mysqld  mysqld               [.] mysqld_stmt_execute(THD*, char*, unsigned int)
  0,46%  mysqld  mysqld               [.] handler::index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function)
  0,46%  mysqld  mysqld               [.] Item_equal::select_optimize() const
  0,46%  mysqld  mysqld               [.] Item_func::used_tables() const
  0,46%  mysqld  mysqld               [.] ha_innobase::info(unsigned int)
  0,46%  mysqld  libc-2.13.so         [.] __memmove_ssse3
  0,46%  mysqld  libc-2.13.so         [.] __memcmp_sse4_1
  0,46%  mysqld  [kernel.kallsyms]    [k] dequeue_task_fair
  0,46%  mysqld  [kernel.kallsyms]    [k] pick_next_task_fair
  0,38%  mysqld  mysqld               [.] Protocol_binary::store(char const*, unsigned long, charset_info_st const*)
  0,38%  mysqld  mysqld               [.] Protocol::send_result_set_metadata(List<Item>*, unsigned int)

Instructions retired (INST_RETIRED.ANY), after PGO:

Samples: 166K of event 'rc0', Event count (approx.): 166686
  2,55%  mysqld  libc-2.13.so         [.] __memcpy_ssse3
  1,79%  mysqld  mysqld               [.] my_hash_sort_bin
  1,60%  mysqld  mysqld               [.] alloc_root
  1,48%  mysqld  mysqld               [.] malloc
  1,42%  mysqld  mysqld               [.] my_malloc_size_cb_func
  1,42%  mysqld  mysqld               [.] free
  1,29%  mysqld  libc-2.13.so         [.] __memset_sse2
  1,23%  mysqld  libpthread-2.13.so   [.] __pthread_mutex_unlock_usercnt
  1,20%  mysqld  mysqld               [.] ha_innobase::build_template(bool)
  1,16%  mysqld  libpthread-2.13.so   [.] pthread_mutex_lock
  1,15%  mysqld  mysqld               [.] make_join_statistics(JOIN*, List<TABLE_LIST>&, Item*, st_dynamic_array*)
  1,15%  mysqld  mysqld               [.] JOIN::save_explain_data_intern(Explain_query*, bool, bool, bool, char const*)
  1,13%  mysqld  mysqld               [.] JOIN::optimize_inner()
  1,12%  mysqld  mysqld               [.] build_template_field(row_prebuilt_t*, dict_index_t*, dict_index_t*, TABLE*, Field const*, unsigned long)
  1,07%  mysqld  [vdso]               [.] 0x00000000000006a1
  1,03%  mysqld  mysqld               [.] row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
  1,00%  mysqld  libpthread-2.13.so   [.] pthread_getspecific
  0,99%  mysqld  mysqld               [.] THD::enter_stage(PSI_stage_info_none const*, PSI_stage_info_none*, char const*, char const*, unsigned int)
  0,94%  mysqld  libc-2.13.so         [.] __strlen_sse42
  0,83%  mysqld  mysqld               [.] cmp_dtuple_rec_with_match_low(dtuple_t const*, unsigned char const*, unsigned long const*, unsigned long, unsigned long*, unsigned long*)
  0,80%  mysqld  libc-2.13.so         [.] __strcmp_sse42
  0,78%  mysqld  [kernel.kallsyms]    [k] unix_stream_recvmsg
  0,78%  mysqld  mysqld               [.] Protocol::net_store_data(unsigned char const*, unsigned long, charset_info_st const*, charset_info_st const*)
  0,75%  mysqld  mysqld               [.] rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, unsigned long, mem_block_info_t**, char const*, unsigned long)
  0,69%  mysqld  mysqld               [.] JOIN::prepare(Item***, TABLE_LIST*, unsigned int, Item*, unsigned int, st_order*, bool, st_order*, Item*, st_order*, st_select_lex*, st_select_lex_unit*)
  0,68%  mysqld  mysqld               [.] _ZL19update_ref_and_keysP3THDP16st_dynamic_arrayP13st_join_tablejP4ItemyP13st_select_lexPP17st_sargable_param.isra.183
  0,68%  mysqld  [kernel.kallsyms]    [k] _raw_spin_lock_irqsave
  0,63%  mysqld  [kernel.kallsyms]    [k] effective_load
  0,63%  mysqld  mysqld               [.] mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_
  0,62%  mysqld  mysqld               [.] create_ref_for_key(JOIN*, st_join_table*, keyuse_t*, bool, unsigned long long)
  0,59%  mysqld  [kernel.kallsyms]    [k] _raw_spin_unlock_irqrestore
  0,57%  mysqld  [kernel.kallsyms]    [k] select_task_rq_fair
  0,56%  mysqld  [kernel.kallsyms]    [k] update_cfs_shares
  0,56%  mysqld  mysqld               [.] open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)
  0,52%  mysqld  [kernel.kallsyms]    [k] update_curr
  0,52%  mysqld  mysqld               [.] Protocol::send_result_set_metadata(List<Item>*, unsigned int)
  0,52%  mysqld  mysqld               [.] ha_innobase::external_lock(THD*, int)
  0,51%  mysqld  mysqld               [.] my_malloc
  0,50%  mysqld  [kernel.kallsyms]    [k] update_entity_load_avg
  0,46%  mysqld  mysqld               [.] dispatch_command(enum_server_command, THD*, char*, unsigned int)
  0,46%  mysqld  [kernel.kallsyms]    [k] copy_user_generic_string
  0,45%  mysqld  mysqld               [.] btr_search_guess_on_hash(dict_index_t*, btr_search_t*, dtuple_t const*, unsigned long, unsigned long, btr_cur_t*, unsigned long, mtr_t*)
  0,43%  mysqld  mysqld               [.] get_best_combination(JOIN*)
  0,43%  mysqld  [kernel.kallsyms]    [k] do_raw_spin_lock
  0,42%  mysqld  mysqld               [.] find_field_in_table(THD*, TABLE*, char const*, unsigned int, bool, unsigned int*)
  0,42%  mysqld  [kernel.kallsyms]    [k] enqueue_task_fair
  0,41%  mysqld  [kernel.kallsyms]    [k] account_entity_enqueue
  0,39%  mysqld  [kernel.kallsyms]    [k] init_sync_kiocb.constprop.15
  0,39%  mysqld  mysqld               [.] sort_and_filter_keyuse(THD*, st_dynamic_array*, bool)
  0,39%  mysqld  mysqld               [.] mysql_execute_command(THD*)
  0,38%  mysqld  mysqld               [.] my_lengthsp_8bit
  0,38%  mysqld  [kernel.kallsyms]    [k] system_call
  0,38%  mysqld  mysqld               [.] lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int)
  0,37%  mysqld  mysqld               [.] Item::Item()
  0,36%  mysqld  [kernel.kallsyms]    [k] atomic64_dec_and_test
  0,35%  mysqld  librt-2.13.so        [.] clock_gettime
  0,34%  mysqld  mysqld               [.] JOIN::cleanup(bool)
  0,34%  mysqld  mysqld               [.] Item_func::type() const
  0,33%  mysqld  mysqld               [.] dict_index_copy_types(dtuple_t*, dict_index_t const*, unsigned long)
  0,33%  mysqld  mysqld               [.] MDL_context::try_acquire_lock_impl(MDL_request*, MDL_ticket**)
  0,33%  mysqld  [kernel.kallsyms]    [k] __update_tg_runnable_avg.isra.25

Icache misses (ICACHE.MISSES), after PGO:

Samples: 13K of event 'r280', Event count (approx.): 13643
  2,07%  mysqld  libc-2.13.so         [.] __memcpy_ssse3
  1,39%  mysqld  mysqld               [.] malloc
  1,33%  mysqld  mysqld               [.] JOIN::optimize_inner()
  1,26%  mysqld  mysqld               [.] JOIN::save_explain_data_intern(Explain_query*, bool, bool, bool, char const*)
  1,17%  mysqld  mysqld               [.] make_join_statistics(JOIN*, List<TABLE_LIST>&, Item*, st_dynamic_array*)
  1,08%  mysqld  [vdso]               [.] 0x0000000000000864
  1,07%  mysqld  mysqld               [.] row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
  1,06%  mysqld  libc-2.13.so         [.] __memset_sse2
  1,01%  mysqld  mysqld               [.] free
  0,97%  mysqld  libpthread-2.13.so   [.] pthread_mutex_lock
  0,92%  mysqld  [kernel.kallsyms]    [k] _raw_spin_lock_irqsave
  0,80%  mysqld  mysqld               [.] THD::enter_stage(PSI_stage_info_none const*, PSI_stage_info_none*, char const*, char const*, unsigned int)
  0,76%  mysqld  mysqld               [.] alloc_root
  0,74%  mysqld  libpthread-2.13.so   [.] __pthread_mutex_unlock_usercnt
  0,73%  mysqld  libc-2.13.so         [.] __strcmp_sse42
  0,71%  mysqld  mysqld               [.] open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*)
  0,69%  mysqld  mysqld               [.] my_hash_sort_bin
  0,67%  mysqld  [kernel.kallsyms]    [k] fget_light
  0,63%  mysqld  [kernel.kallsyms]    [k] do_raw_spin_lock
  0,62%  mysqld  mysqld               [.] mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_
  0,59%  mysqld  mysqld               [.] Item::Item()
  0,57%  mysqld  mysqld               [.] _ZL19update_ref_and_keysP3THDP16st_dynamic_arrayP13st_join_tablejP4ItemyP13st_select_lexPP17st_sargable_param.isra.183
  0,53%  mysqld  libpthread-2.13.so   [.] pthread_getspecific
  0,52%  mysqld  [kernel.kallsyms]    [k] update_cfs_shares
  0,51%  mysqld  mysqld               [.] ha_innobase::external_lock(THD*, int)
  0,51%  mysqld  mysqld               [.] my_malloc_size_cb_func
  0,50%  mysqld  mysqld               [.] JOIN::prepare(Item***, TABLE_LIST*, unsigned int, Item*, unsigned int, st_order*, bool, st_order*, Item*, st_order*, st_select_lex*, st_select_lex_unit*)
  0,48%  mysqld  mysqld               [.] mysql_execute_command(THD*)
  0,47%  mysqld  mysqld               [.] free_root
  0,47%  mysqld  [kernel.kallsyms]    [k] idle_cpu
  0,47%  mysqld  [kernel.kallsyms]    [k] unix_stream_sendmsg
  0,46%  mysqld  [kernel.kallsyms]    [k] system_call
  0,44%  mysqld  [kernel.kallsyms]    [k] unix_stream_recvmsg
  0,43%  mysqld  mysqld               [.] ha_innobase::info_low(unsigned int, bool)
  0,43%  mysqld  mysqld               [.] MDL_context::try_acquire_lock_impl(MDL_request*, MDL_ticket**)
  0,43%  mysqld  librt-2.13.so        [.] clock_gettime
  0,43%  mysqld  [kernel.kallsyms]    [k] enqueue_task_fair
  0,42%  mysqld  mysqld               [.] JOIN::init(THD*, List<Item>&, unsigned long long, select_result*)
  0,42%  mysqld  mysqld               [.] Item_field::used_tables() const
  0,41%  mysqld  mysqld               [.] create_ref_for_key(JOIN*, st_join_table*, keyuse_t*, bool, unsigned long long)
  0,40%  mysqld  mysqld               [.] Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*)
  0,40%  mysqld  [kernel.kallsyms]    [k] emulate_vsyscall
  0,40%  mysqld  mysqld               [.] dict_index_copy_types(dtuple_t*, dict_index_t const*, unsigned long)
  0,40%  mysqld  [kernel.kallsyms]    [k] update_rq_clock
  0,39%  mysqld  mysqld               [.] dispatch_command(enum_server_command, THD*, char*, unsigned int)
  0,38%  mysqld  mysqld               [.] ha_innobase::extra(ha_extra_function)
  0,38%  mysqld  [kernel.kallsyms]    [k] update_entity_load_avg
  0,37%  mysqld  mysqld               [.] get_best_combination(JOIN*)
  0,37%  mysqld  mysqld               [.] Item_field::fix_fields(THD*, Item**)
  0,37%  mysqld  mysqld               [.] my_malloc
  0,37%  mysqld  [kernel.kallsyms]    [k] __perf_event_task_sched_out
  0,37%  mysqld  [kernel.kallsyms]    [k] __schedule
  0,36%  mysqld  mysqld               [.] lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int)
  0,36%  mysqld  mysqld               [.] mysqld_stmt_execute(THD*, char*, unsigned int)
  0,35%  mysqld  mysqld               [.] Protocol::send_result_set_metadata(List<Item>*, unsigned int)
  0,35%  mysqld  mysqld               [.] Prepared_statement::execute(String*, bool)
  0,34%  mysqld  mysqld               [.] thd_ha_data
  0,34%  mysqld  mysqld               [.] ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function)
  0,34%  mysqld  [kernel.kallsyms]    [k] select_task_rq_fair
  0,34%  mysqld  [kernel.kallsyms]    [k] do_sys_poll
  0,34%  mysqld  mysqld               [.] st_select_lex::master_unit()

Branch mispredictions (BR_MISP_RETIRED.ALL_BRANCHES_PS), after PGO:

Samples: 1K of event 'rc5:p', Event count (approx.): 1147
  8,37%  mysqld  libc-2.13.so         [.] __memcpy_ssse3
  7,06%  mysqld  libpthread-2.13.so   [.] pthread_getspecific
  3,84%  mysqld  mysqld               [.] Item_func::type() const
  2,88%  mysqld  libc-2.13.so         [.] __memset_sse2
  2,70%  mysqld  libpthread-2.13.so   [.] pthread_mutex_lock
  2,35%  mysqld  mysqld               [.] st_select_lex::master_unit()
  2,27%  mysqld  libpthread-2.13.so   [.] pthread_mutex_unlock
  2,18%  mysqld  mysqld               [.] Item_param::used_tables() const
  2,01%  mysqld  mysqld               [.] Field_long::type() const
  2,01%  mysqld  libc-2.13.so         [.] __strlen_sse42
  1,92%  mysqld  libc-2.13.so         [.] __strcmp_sse42
  1,39%  mysqld  mysqld               [.] Item::const_item() const
  1,31%  mysqld  mysqld               [.] ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function)
  1,22%  mysqld  mysqld               [.] handler::index_read_idx_map(unsigned char*, unsigned int, unsigned char const*, unsigned long, ha_rkey_function)
  1,13%  mysqld  mysqld               [.] dispatch_command(enum_server_command, THD*, char*, unsigned int)
  1,13%  mysqld  mysqld               [.] end_send(JOIN*, st_join_table*, bool)
  1,05%  mysqld  mysqld               [.] my_real_read(st_net*, unsigned long*)
  1,05%  mysqld  mysqld               [.] Item_equal::functype() const
  1,05%  mysqld  mysqld               [.] Item_bool_func2::cleanup()
  0,96%  mysqld  mysqld               [.] Item::is_expensive()
  0,96%  mysqld  mysqld               [.] Item_field::type() const
  0,96%  mysqld  mysqld               [.] Item_param::type() const
  0,87%  mysqld  mysqld               [.] Item::real_item()
  0,78%  mysqld  mysqld               [.] Item_field::used_tables() const
  0,78%  mysqld  mysqld               [.] scheduler_wait_net_end
  0,78%  mysqld  librt-2.13.so        [.] clock_gettime
  0,70%  mysqld  mysqld               [.] Statement::set_statement(Statement*)
  0,70%  mysqld  mysqld               [.] _ZL21join_read_const_tableP13st_join_tableP11st_position.isra.180
  0,70%  mysqld  mysqld               [.] JOIN::optimize()
  0,70%  mysqld  mysqld               [.] Field_num::size_of() const
  0,70%  mysqld  mysqld               [.] Field_str::charset() const
  0,70%  mysqld  mysqld               [.] Item_field::cleanup()
  0,70%  mysqld  libpthread-2.13.so   [.] pthread_rwlock_rdlock
  0,61%  mysqld  mysqld               [.] select_result::initialize_tables(JOIN*)
  0,61%  mysqld  mysqld               [.] mysql_execute_command(THD*)
  0,61%  mysqld  mysqld               [.] mysqld_stmt_execute(THD*, char*, unsigned int)
  0,61%  mysqld  mysqld               [.] JOIN::optimize_inner()
  0,61%  mysqld  mysqld               [.] Field_str::decimals() const
  0,61%  mysqld  mysqld               [.] handler::rebind_psi()
  0,61%  mysqld  mysqld               [.] Item_field::field_type() const
  0,61%  mysqld  mysqld               [.] Item::cmp_type() const
  0,52%  mysqld  mysqld               [.] net_before_header_psi(st_net*, void*, unsigned long)
  0,52%  mysqld  mysqld               [.] my_net_read
  0,52%  mysqld  mysqld               [.] mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_
  0,52%  mysqld  mysqld               [.] Field::new_key_field(st_mem_root*, TABLE*, unsigned char*, unsigned char*, unsigned int)
  0,52%  mysqld  mysqld               [.] Field::send_binary(Protocol*)
  0,52%  mysqld  mysqld               [.] row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
  0,52%  mysqld  mysqld               [.] btr_search_guess_on_hash(dict_index_t*, btr_search_t*, dtuple_t const*, unsigned long, unsigned long, btr_cur_t*, unsigned long, mtr_t*)
  0,52%  mysqld  [vdso]               [.] 0x0000000000000630
  0,44%  mysqld  mysqld               [.] Protocol::send_eof(unsigned int, unsigned int)
  0,44%  mysqld  mysqld               [.] Item::has_subquery() const
  0,44%  mysqld  mysqld               [.] Item::mark_as_condition_AND_part(TABLE_LIST*)
  0,44%  mysqld  mysqld               [.] select_send::send_eof()
  0,44%  mysqld  mysqld               [.] select_send::send_data(List<Item>&)
  0,44%  mysqld  mysqld               [.] add_key_fields(JOIN*, key_field_t**, unsigned int*, Item*, unsigned long long, st_sargable_param**)
  0,44%  mysqld  mysqld               [.] do_handle_one_connection(THD*)
  0,44%  mysqld  mysqld               [.] Field_str::repertoire() const
  0,44%  mysqld  mysqld               [.] handler::cancel_pushed_idx_cond()
  0,44%  mysqld  mysqld               [.] Item_field::get_item_equal()
  0,44%  mysqld  mysqld               [.] Item::check_cols(unsigned int)
  0,44%  mysqld  mysqld               [.] Item_field::fix_fields(THD*, Item**)

Tags: , , , ,

(4 comments | Leave a comment)

Comments
 
[User Picture]
From:bludwarf
Date:January 24th, 2014 06:27 pm (UTC)
(Link)
Hi Kristian,

very interesting results.

Before PGO my_hash_sort_bin was the second just after the hottest spot (__memcpy_ssse3) - 1,92% and 1,94% correspondingly. After the optimization it's still the second, but the gap is significantly larger - 2,55% and 1,79%. So it seems the function was optimized. Actually, it's just a simple loop calculating a hash, so it's assembly code should be very short. Is it possible to have a look at the assembly for the function before and after PGO? Maybe there is some cycle unrolling?.. The loop depends on input data (key) so probably compiler unrolls some iterations?..
From:kristiannielsen
Date:January 24th, 2014 07:26 pm (UTC)
(Link)
Looks like the compiler detected that the code is run sufficiently often that
it decided to unroll the loop a couple of times. See dissasembly here:
http://knielsen-hq.dk/pgo-disassembly.txt

However, note that this profile is about instructions retired, and
my_hash_sort_bin() did not change that much. The reason for the larger gap
seems to be that the compiler decided to use __memcpy_ssse3() in more places
(instead of inline rep movsb), hence more instructions are executed inside it.

I also noticed that the my_hash_sort_bin() function is written poorly. The
compiler is forced to store and re-load the nr1[0] and nr2[0] values in each
iteration, which is very costly - but this is necessary, otherwise the
semantics would be wrong in case nr1 and nr2 alias with one another (or with
key). Of course, they never alias in practise, but the compiler does not know
this. I will fix this (__restrict might work, but it is easier to just copy
into and out of temporary variables).

And thanks for you interesting observations and comments, keep them coming :-)

- Kristian.
From:https://flexichat.net/lulu-openid
Date:January 25th, 2014 09:19 am (UTC)
(Link)
my results on x86 architecture, mariadb 10.0.7

http://lulu.jong.my/mariadb-pro-bench.png
From:kristiannielsen
Date:January 27th, 2014 09:49 am (UTC)
(Link)
Nice, thanks for testing :-) Pretty good results, those!
Powered by LiveJournal.com