Announcement

Announcement Module
Collapse
No announcement yet.

Unusual long time spent on storing result in query cache

Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Unusual long time spent on storing result in query cache

    I have a quite complex query, using seven joins over three tables, that sometimes takes an unusual time to execute.

    Normally the query finishes within seconds, but once in a while the queries pile up and the processlist starts to fill up with this specific query, causing them to take about 300-400 seconds per query. This is usually the moment I'm getting calls from our users and start killing away these queries.

    Weird thing is that if I profile such a query at the moment they are hanging, all time is spent on storing the result in the query cache, e.g.:

    +----------+-----+--------------------------------+--------- ---+----------+------------+-------------------+------------ ---------+--------------+---------------+---------------+--- ----------------+-------------------+-------------------+--- ----+-----------------------+---------------+-------------+
    | QUERY_ID | SEQ | STATE | DURATION | CPU_USER | CPU_SYSTEM | CONTEXT_VOLUNTARY | CONTEXT_INVOLUNTARY | BLOCK_OPS_IN | BLOCK_OPS_OUT | MESSAGES_SENT | MESSAGES_RECEIVED | PAGE_FAULTS_MAJOR | PAGE_FAULTS_MINOR | SWAPS | SOURCE_FUNCTION | SOURCE_FILE | SOURCE_LINE |
    +----------+-----+--------------------------------+--------- ---+----------+------------+-------------------+------------ ---------+--------------+---------------+---------------+--- ----------------+-------------------+-------------------+--- ----+-----------------------+---------------+-------------+
    | 1 | 1 | starting | 0.000066 | 0.000000 | 0.000194 | 3 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
    | 1 | 2 | checking query cache for query | 0.000249 | 0.000000 | 0.000748 | 16 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1143 |
    | 1 | 3 | Opening tables | 0.000097 | 0.000000 | 0.000349 | 6 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 2664 |
    | 1 | 4 | System lock | 0.000024 | 0.000000 | 0.000060 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 153 |
    | 1 | 5 | Table lock | 0.000085 | 0.000000 | 0.000358 | 7 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 163 |
    | 1 | 6 | init | 0.000115 | 0.000000 | 0.000477 | 8 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 2275 |
    | 1 | 7 | optimizing | 0.000051 | 0.000000 | 0.000229 | 2 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_select.cc | 759 |
    | 1 | 8 | statistics | 0.023570 | 0.000000 | 0.066565 | 1678 | 18 | 0 | 0 | 10 | 20 | 0 | 0 | 0 | optimize | sql_select.cc | 912 |
    | 1 | 9 | preparing | 0.000072 | 0.000000 | 0.000190 | 5 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_select.cc | 922 |
    | 1 | 10 | executing | 0.000031 | 0.000000 | 0.000108 | 2 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_select.cc | 1591 |
    | 1 | 11 | Sorting result | 0.000021 | 0.000000 | 0.000047 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_select.cc | 1991 |
    | 1 | 12 | Sending data | 0.013143 | 0.000000 | 0.041227 | 952 | 58 | 0 | 0 | 18 | 32 | 0 | 0 | 0 | exec | sql_select.cc | 2115 |
    | 1 | 13 | storing result in query cache | 232.595520 | 0.000000 | 488.715455 | 18629139 | 361433 | 22 | 4067 | 40458 | 75736 | 0 | 9232 | 0 | query_cache_abort | sql_cache.cc | 691 |
    | 1 | 14 | end | 0.000019 | 0.000000 | 0.000067 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 2320 |
    | 1 | 15 | end | 0.000007 | 0.000000 | 0.000028 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 2322 |
    | 1 | 16 | query end | 0.000008 | 0.000000 | 0.000031 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5329 |
    | 1 | 17 | freeing items | 0.000041 | 0.000000 | 0.000165 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 6340 |
    | 1 | 18 | closing tables | 0.000010 | 0.000000 | 0.000041 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 2306 |
    | 1 | 19 | logging slow query | 0.000006 | 0.000000 | 0.000024 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | log_slow_statement | sql_parse.cc | 2364 |
    | 1 | 20 | logging slow query | 0.000040 | 0.000000 | 0.000161 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | log_slow_statement | sql_parse.cc | 2374 |
    | 1 | 21 | cleaning up | 0.000019 | 0.000000 | 0.000076 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 2329 |
    +----------+-----+--------------------------------+--------- ---+----------+------------+-------------------+------------ ---------+--------------+---------------+---------------+--- ----------------+-------------------+-------------------+--- ----+-----------------------+---------------+-------------+


    The system is running FreeBSD 6.4, MySQL 5.0.77 and all tables are InnoDB. Cache parameters:

    | query_cache_limit | 1048576 |
    | query_cache_min_res_unit | 4096 |
    | query_cache_size | 16777216 |
    | query_cache_type | ON |
    | query_cache_wlock_invalidate | OFF |

    Has somebody seen this kind of behavior before? Please let me know if you need more information, parameters, schema's, queries, etc.

  • #2
    And possibly of interest:

    +-------------------------+-----------+
    | Variable_name | Value |
    +-------------------------+-----------+
    | Qcache_free_blocks | 1921 |
    | Qcache_free_memory | 5580504 |
    | Qcache_hits | 848105931 |
    | Qcache_inserts | 54312258 |
    | Qcache_lowmem_prunes | 10197256 |
    | Qcache_not_cached | 288569871 |
    | Qcache_queries_in_cache | 4528 |
    | Qcache_total_blocks | 11184 |
    +-------------------------+-----------+

    Comment


    • #3
      When the queries all pile up, what status are the other queries in?

      How many CPUs do you have and about how many queries per second does your server typically run? 100, 1000, 10000?

      The reason that I ask is that the query cache doesn't scale on SMP hardware, period. It is becoming increasingly common for us to find cases where it is intermittently locking the whole server, and the solution is to turn it off.

      If you can catch the server during one of the freezes, use poor man's profiler http://poormansprofiler.org/ to stack-dump it and let's see what it is doing. There are tools in http://code.google.com/p/aspersa/ (stalk and collect) that can help with this.

      Comment


      • #4
        Ouch! That doesn't sound good: the server has 8 CPU's.

        It runs an average of 500 QPS, with peaks at 2000.

        When queries pile up, there are about 5 identical queries that are taking more than 200 seconds and are all in 'storing result in query cache', other queries are at random states like 'Sorting result' or 'Sending data', sometimes also taking forever. This leads to ridiculous entries in the slow query log, like:

        # Query_time: 107 Lock_time: 0 Rows_sent: 1351 Rows_examined: 1351
        select filename, size, state from files where server='9f0u34';

        In normal circumstances this query wouldn't even be measurable fast.

        Isn't it strange that it is always the same query that locks the query cache then? If it's a locking issue I would expect different queries to keep hanging.

        I've set up the poormansprofiler for FreeBSD so I can produce a stacktrace when it occurs again. MySQL is compiled without debug symbols though, so I don't expect to find anything useful in there.

        I'm not sure if I'll disable the cache, constrain MySQL to one processor or add a SQL_NO_CACHE-keyword to the query.

        Thanks for your advice!

        Comment


        • #5
          Ok! Got some traces from poormansprofiler:

          53 read,read,vio_read,select_max_min_finder_subselect ::cmp_str,select_max_min_finder_subselect::cmp_str ,handle_one_connection,pthread_mutexattr_init,?? 4 pthread_mutexattr_init,pthread_mutexattr_init,_pth read_cond_wait,pthread_cond_wait,trx_rollback_or_c lean_all_without_sess,trx_rollback_or_clean_all_wi thout_sess,trx_rollback_or_clean_all_without_sess, srv_master_thread,pthread_create,_ctx_start 2 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,srv_master_thread,srv_master_thread,innobase_q uery_caching_of_table_permitted,_my_b_net_read,_my _b_net_read,_my_b_net_read,sub_select_cache,sub_se lect_cache,sub_select_cache,test_if_data_home_dir, test_if_data_home_dir,test_if_data_home_dir,handle _one_connection,pthread_mutexattr_init,?? 2 pthread_testcancel,pthread_mutexattr_init,?? 1 select,select,handle_segfault,handle_segfault,??,? ?,??,??,my_str_malloc,__moddi3,?? 1 read,read,vio_read,select_max_min_finder_subselect ::cmp_str,select_max_min_finder_subselect::cmp_str ,handle_one_connection,pthread_mutexattr_init,??,p thread_testcancel 1 pthread_testcancel,sigwait,signal_hand,pthread_mut exattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,_pthread_con d_wait,pthread_cond_wait,kill_server_thread,handle _one_connection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,_pthread_con d_wait,pthread_cond_wait,handle_manager,pthread_mu texattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_lock,trx_rollback_or_clean_all_without_s ess,trx_rollback_or_clean_all_without_sess,trx_rol lback_or_clean_all_without_sess,srv_master_thread, srv_master_thread,innobase_query_caching_of_table_ permitted,sub_select,sub_select,table_cache_key,su b_select,table_cache_key,sub_select,table_cache_ke y,sub_select,sub_select,sub_select_cache,sub_selec t_cache,sub_select_cache,test_if_data_home_dir,tes t_if_data_home_dir,test_if_data_home_dir,handle_on e_connection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,table_cache_key,sub_select,table _cache_key,sub_select,sub_select,sub_select_cache, sub_select_cache,sub_select_cache,test_if_data_hom e_dir,test_if_data_home_dir,test_if_data_home_dir, handle_one_connection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,table_cache_key,sub_select,table _cache_key,sub_select,sub_select,sub_select_cache, sub_select_cache,mysql_derived_filling,log_loaded_ block,table_cache_key,test_if_data_home_dir,test_i f_data_home_dir,test_if_data_home_dir,handle_one_c onnection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,sub_select,table_cache_key,sub_s elect,table_cache_key,sub_select,sub_select,sub_se lect_cache,sub_select_cache,mysql_derived_filling, log_loaded_block,table_cache_key,test_if_data_home _dir,test_if_data_home_dir,test_if_data_home_dir,h andle_one_connection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,sub_select,table_cache_key,sub_s elect,sub_select,sub_select,sub_select,table_cache _key,sub_select,table_cache_key,sub_select,sub_sel ect,sub_select_cache,sub_select_cache,sub_select_c ache,test_if_data_home_dir,test_if_data_home_dir,t est_if_data_home_dir,handle_one_connection,pthread _mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,QUIC K_ROR_UNION_SELECT::queue_cmp,QUICK_ROR_UNION_SELE CT::queue_cmp,QUICK_ROR_UNION_SELECT::queue_cmp,QU ICK_ROR_UNION_SELECT::queue_cmp,sub_select,sub_sel ect_cache,sub_select_cache,sub_select_cache,test_i f_data_home_dir,test_if_data_home_dir,test_if_data _home_dir,handle_one_connection,pthread_mutexattr_ init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,srv_master_thread,srv _master_thread,innobase_query_caching_of_table_per mitted,sub_select,sub_select,table_cache_key,sub_s elect,table_cache_key,sub_select,table_cache_key,s ub_select,sub_select,sub_select_cache,sub_select_c ache,sub_select_cache,test_if_data_home_dir,test_i f_data_home_dir,test_if_data_home_dir,handle_one_c onnection,pthread_mutexattr_init,?? 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_master _thread,pthread_create,_ctx_start 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_lock_t imeout_and_monitor_thread,pthread_create,_ctx_star t 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_error_ monitor_thread,pthread_create,_ctx_start 55 read,read,vio_read,select_max_min_finder_subselect ::cmp_str,select_max_min_finder_subselect::cmp_str ,handle_one_connection,pthread_mutexattr_init,?? 4 pthread_mutexattr_init,pthread_mutexattr_init,_pth read_cond_wait,pthread_cond_wait,trx_rollback_or_c lean_all_without_sess,trx_rollback_or_clean_all_wi thout_sess,trx_rollback_or_clean_all_without_sess, srv_master_thread,pthread_create,_ctx_start 2 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,srv_master_thread,srv_master_thread,innobase_q uery_caching_of_table_permitted,_my_b_net_read,_my _b_net_read,_my_b_net_read,sub_select_cache,sub_se lect_cache,sub_select_cache,test_if_data_home_dir, test_if_data_home_dir,test_if_data_home_dir,handle _one_connection,pthread_mutexattr_init,?? 2 pthread_testcancel,pthread_mutexattr_init,?? 1 select,select,handle_segfault,handle_segfault,??,? ?,??,??,my_str_malloc,__moddi3,?? 1 read,read,vio_read,select_max_min_finder_subselect ::cmp_str,select_max_min_finder_subselect::cmp_str ,handle_one_connection,pthread_mutexattr_init,??,p thread_testcancel 1 pthread_testcancel,sigwait,signal_hand,pthread_mut exattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,_pthread_con d_wait,pthread_cond_wait,handle_manager,pthread_mu texattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_lock,trx_rollback_or_clean_all_without_s ess,trx_rollback_or_clean_all_without_sess,trx_rol lback_or_clean_all_without_sess,srv_master_thread, srv_master_thread,innobase_query_caching_of_table_ permitted,sub_select,sub_select,table_cache_key,su b_select,table_cache_key,sub_select,table_cache_ke y,sub_select,sub_select,sub_select_cache,sub_selec t_cache,mysql_derived_filling,log_loaded_block,tab le_cache_key,test_if_data_home_dir,test_if_data_ho me_dir,test_if_data_home_dir,handle_one_connection ,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,srv_master_thread,innobase_query_caching_of_ta ble_permitted,innobase_query_caching_of_table_perm itted,ha_init_key_cache,ha_init_key_cache,QUICK_RO R_UNION_SELECT::queue_cmp,rr_sequential,join_read_ next_same_or_null,sub_select_cache,sub_select_cach e,sub_select_cache,test_if_data_home_dir,test_if_d ata_home_dir,test_if_data_home_dir,handle_one_conn ection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,table_cache_key,sub_select,table _cache_key,sub_select,table_cache_key,sub_select,s ub_select,sub_select_cache,sub_select_cache,mysql_ derived_filling,log_loaded_block,table_cache_key,t est_if_data_home_dir,test_if_data_home_dir,test_if _data_home_dir,handle_one_connection,pthread_mutex attr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,table_cache_key,sub_select,table _cache_key,sub_select,sub_select,sub_select_cache, sub_select_cache,sub_select_cache,test_if_data_hom e_dir,test_if_data_home_dir,test_if_data_home_dir, handle_one_connection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,table_cache_key,sub_select,sub_s elect,table_cache_key,sub_select,sub_select,table_ cache_key,sub_select,table_cache_key,sub_select,ta ble_cache_key,sub_select,sub_select,sub_select_cac he,sub_select_cache,sub_select_cache,test_if_data_ home_dir,test_if_data_home_dir,test_if_data_home_d ir,handle_one_connection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,sub_select,table_cache_key,sub_s elect,table_cache_key,sub_select,sub_select,sub_se lect_cache,sub_select_cache,sub_select_cache,test_ if_data_home_dir,test_if_data_home_dir,test_if_dat a_home_dir,handle_one_connection,pthread_mutexattr _init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,sub_select,sub_select,table_cach e_key,sub_select,table_cache_key,sub_select,table_ cache_key,sub_select,sub_select,sub_select_cache,s ub_select_cache,sub_select_cache,test_if_data_home _dir,test_if_data_home_dir,test_if_data_home_dir,h andle_one_connection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,srv_master_thread,srv _master_thread,srv_master_thread,srv_master_thread ,innobase_query_caching_of_table_permitted,_my_b_n et_read,_my_b_net_read,_my_b_net_read,sub_select_c ache,sub_select_cache,sub_select_cache,test_if_dat a_home_dir,test_if_data_home_dir,test_if_data_home _dir,handle_one_connection,pthread_mutexattr_init, ?? 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_master _thread,pthread_create,_ctx_start 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_lock_t imeout_and_monitor_thread,pthread_create,_ctx_star t 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_error_ monitor_thread,pthread_create,_ctx_start 1 nanosleep,_nanosleep,nanosleep,select,trx_rollback _or_clean_all_without_sess,__memp_fget,innobase_qu ery_caching_of_table_permitted,sub_select,sub_sele ct,sub_select,table_cache_key,sub_select,table_cac he_key,sub_select,sub_select,sub_select_cache,sub_ select_cache,mysql_derived_filling,log_loaded_bloc k,table_cache_key,test_if_data_home_dir,test_if_da ta_home_dir,test_if_data_home_dir,handle_one_conne ction,pthread_mutexattr_init,?? 1 nanosleep,_nanosleep,nanosleep,select,trx_rollback _or_clean_all_without_sess,__memp_fget,innobase_qu ery_caching_of_table_permitted,innobase_query_cach ing_of_table_permitted,sub_select,sub_select,sub_s elect,sub_select_cache,sub_select_cache,sub_select _cache,test_if_data_home_dir,test_if_data_home_dir ,test_if_data_home_dir,handle_one_connection,pthre ad_mutexattr_init,?? 53 read,read,vio_read,select_max_min_finder_subselect ::cmp_str,select_max_min_finder_subselect::cmp_str ,handle_one_connection,pthread_mutexattr_init,?? 4 pthread_mutexattr_init,pthread_mutexattr_init,_pth read_cond_wait,pthread_cond_wait,trx_rollback_or_c lean_all_without_sess,trx_rollback_or_clean_all_wi thout_sess,trx_rollback_or_clean_all_without_sess, srv_master_thread,pthread_create,_ctx_start 2 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,_pthread_con d_wait,pthread_cond_wait,trx_rollback_or_clean_all _without_sess,__memp_fget,innobase_query_caching_o f_table_permitted,innobase_query_caching_of_table_ permitted,sub_select,sub_select,sub_select,sub_sel ect_cache,sub_select_cache,sub_select_cache,test_i f_data_home_dir,test_if_data_home_dir,test_if_data _home_dir,handle_one_connection,pthread_mutexattr_ init,?? 2 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,_pthread_con d_wait,pthread_cond_wait,kill_server_thread,handle _one_connection,pthread_mutexattr_init,?? 2 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,table_cache_key,sub_select,table _cache_key,sub_select,table_cache_key,sub_select,s ub_select,sub_select_cache,sub_select_cache,mysql_ derived_filling,log_loaded_block,table_cache_key,t est_if_data_home_dir,test_if_data_home_dir,test_if _data_home_dir,handle_one_connection,pthread_mutex attr_init,?? 2 pthread_testcancel,pthread_mutexattr_init,?? 1 srv_master_thread,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,inno base_query_caching_of_table_permitted,ha_init_key_ cache,ha_init_key_cache,QUICK_ROR_UNION_SELECT::qu eue_cmp,rr_sequential,join_read_next_same_or_null, sub_select_cache,sub_select_cache,sub_select_cache ,test_if_data_home_dir,test_if_data_home_dir,test_ if_data_home_dir,handle_one_connection,pthread_mut exattr_init,?? 1 select,select,handle_segfault,handle_segfault,??,? ?,??,??,my_str_malloc,__moddi3,?? 1 read,read,vio_read,select_max_min_finder_subselect ::cmp_str,select_max_min_finder_subselect::cmp_str ,handle_one_connection,pthread_mutexattr_init,??,p thread_testcancel 1 pthread_testcancel,sigwait,signal_hand,pthread_mut exattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,_pthread_con d_wait,pthread_cond_wait,trx_rollback_or_clean_all _without_sess,__memp_fget,innobase_query_caching_o f_table_permitted,innobase_query_caching_of_table_ permitted,sub_select,sub_select,sub_select,sub_sel ect_cache,sql_alloc_error_handler,sql_alloc_error_ handler,sql_alloc_error_handler,view_error_process or,Arg_comparator::compare_e_int_diff_signedness,? ?,??,my_charset_utf8_general_ci,??,select_max_min_ finder_subselect::cmp_str,ull_get_key,??,??,??,??, ??,??,??,??,??,??,my_charset_utf8_general_ci,??,se lect_max_min_finder_subselect::cmp_str,cmp_longlon g,??,??,??,??,??,??,??,??,??,??,??,??,__memp_fget, cmp_longlong,table_cache_key,sub_select,sub_select ,sub_select_cache,sub_select_cache,sub_select_cach e,test_if_data_home_dir,test_if_data_home_dir,test _if_data_home_dir,handle_one_connection,pthread_mu texattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,_pthread_con d_wait,pthread_cond_wait,trx_rollback_or_clean_all _without_sess,__memp_fget,innobase_query_caching_o f_table_permitted,innobase_query_caching_of_table_ permitted,ha_init_key_cache,ha_init_key_cache,QUIC K_ROR_UNION_SELECT::queue_cmp,rr_sequential,join_r ead_next_same_or_null,sub_select_cache,sub_select_ cache,sub_select_cache,test_if_data_home_dir,test_ if_data_home_dir,test_if_data_home_dir,handle_one_ connection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,_pthread_con d_wait,pthread_cond_wait,handle_manager,pthread_mu texattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_lock,trx_rollback_or_clean_all_without_s ess,trx_rollback_or_clean_all_without_sess,trx_rol lback_or_clean_all_without_sess,srv_master_thread, srv_master_thread,innobase_query_caching_of_table_ permitted,sub_select,sub_select,table_cache_key,su b_select,sub_select,table_cache_key,sub_select,tab le_cache_key,sub_select,table_cache_key,sub_select ,sub_select,sub_select_cache,sub_select_cache,sub_ select_cache,test_if_data_home_dir,test_if_data_ho me_dir,test_if_data_home_dir,handle_one_connection ,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,table_cache_key,sub_select,table _cache_key,sub_select,sub_select,sub_select_cache, sub_select_cache,sub_select_cache,test_if_data_hom e_dir,test_if_data_home_dir,test_if_data_home_dir, handle_one_connection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,trx_rollback_or_clean _all_without_sess,srv_master_thread,srv_master_thr ead,innobase_query_caching_of_table_permitted,sub_ select,sub_select,table_cache_key,sub_select,sub_s elect,sub_select,table_cache_key,sub_select,table_ cache_key,sub_select,sub_select,sub_select_cache,s ub_select_cache,sub_select_cache,test_if_data_home _dir,test_if_data_home_dir,test_if_data_home_dir,h andle_one_connection,pthread_mutexattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,__error,pthr ead_mutex_destroy,pthread_mutex_trylock,trx_rollba ck_or_clean_all_without_sess,srv_master_thread,srv _master_thread,innobase_query_caching_of_table_per mitted,sub_select,sub_select,table_cache_key,sub_s elect,sub_select,table_cache_key,sub_select,sub_se lect,sub_select,table_cache_key,sub_select,table_c ache_key,sub_select,sub_select,sub_select_cache,su b_select_cache,sub_select_cache,test_if_data_home_ dir,test_if_data_home_dir,test_if_data_home_dir,ha ndle_one_connection,pthread_mutexattr_init,?? 1 pthread_testcancel,__error,pthread_mutex_destroy,p thread_mutex_trylock,trx_rollback_or_clean_all_wit hout_sess,trx_rollback_or_clean_all_without_sess,s rv_master_thread,srv_master_thread,innobase_query_ caching_of_table_permitted,sub_select,sub_select,t able_cache_key,sub_select,table_cache_key,sub_sele ct,table_cache_key,sub_select,sub_select,sub_selec t_cache,sub_select_cache,mysql_derived_filling,log _loaded_block,table_cache_key,test_if_data_home_di r,test_if_data_home_dir,test_if_data_home_dir,hand le_one_connection,pthread_mutexattr_init,?? 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_master _thread,pthread_create,_ctx_start 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_lock_t imeout_and_monitor_thread,pthread_create,_ctx_star t 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_error_ monitor_thread,pthread_create,_ctx_start


          Does this make any sense to you?

          Comment


          • #6
            If you used the Aspersa tools, you should have SHOW PROCESSLIST at the same time. It looks like you've got about 53 or so identical queries, based on the GDB backtraces. Can you look in your processlist and find those? Post one sample so I can see it.

            Comment


            • #7
              I didn't use the Aspersa-tools, because they only work on Linux (I'm running FreeBSD). I don't have bash, flock, opcontrol, seq, /proc to name some dependencies.

              In the processlist there are surely no 53 queries, but there are about 53 connections, mostly idle ('Sleep').

              Here's the offending query:

              SELECT SQL_CALC_FOUND_ROWS p.*, COUNT(episode.id) as episodeCount, series.title as seriesTitle, parentSeason.value as parentSeason, IF (p.programtype_name = 'series', CONCAT(p.title, ' - S', season.value), p.title) as title FROM program p LEFT JOIN file f ON f.program_id = p.id LEFT JOIN file deriv ON f.id = deriv.parent_id LEFT JOIN program episode ON p.id = episode.parent_id LEFT JOIN program series ON p.parent_id = series.id LEFT JOIN program_fields typeinterstitial on typeinterstitial.primaryKeys = p.id AND typeinterstitial.name = 'nl_typeinterstitial' LEFT JOIN program_fields parentSeason ON series.id = parentSeason.primaryKeys AND parentSeason.name = 'nl_seriesseason' LEFT JOIN program_fields season ON p.id = season.primaryKeys AND season.name = 'nl_seriesseason' WHERE (ISNULL(episode.id) OR episode.enabled) AND p.enabled AND ('%' = '%' OR p.owner_name LIKE '%') AND ('%' = '%' OR p.parent_id = '%') AND p.archived = '%' AND ('%' = '%' OR p.programtype_name = '%') AND (isnull(typeinterstitial.value) OR '%' = '%' OR typeinterstitial.value LIKE '%') AND ('%' = '%' OR p.title LIKE '%' OR p.programtype_name LIKE '%' OR p.owner_name LIKE '%' OR p.id LIKE '%' OR p.programtype_name LIKE '%' or p.owner_name LIKE '%' ) GROUP BY p.id ORDER BY id asc LIMIT 20 OFFSET 0;


              All tables are InnoDB, we use soft deletes (p.enabled) and the table program_fields is used to extend the program-table with miscellaneous fields.

              The wizardry with the '%' is a result of parameter substitution in the query, but the idea is that it all should be shorted out by MySQL anyway (by using '%' = '%' OR ...).

              It might not be the prettiest sight, but does that somehow justify the query cache locking?

              PS> Sorry for killing the forum layout!

              Comment


              • #8
                The forum layout is the forum's problem. We need to upgrade and design a good theme )

                In the stack trace, I see 53 of these:

                read,read,vio_read,select_max_min_finder_subselect ::cmp_str, select_max_min_finder_subselect::cmp_str....

                Those are definitely active queries. If you think they are the query you presented, then probably they are all blocked on IO at the same time. (Reads are blocking; writes are generally not, because they can be buffered.)

                Did you capture IO usage during this time? iostat or vmstat at 1-second intervals?

                Comment


                • #9
                  Here's an update of my findings:

                  First of all, the 53 threads that are in a 'read'-call are not active queries, but sleeping connections. If I simultaneously dump the stacktraces and the processlist on an idle system this becomes apparent:
                  #./poormansprofiler.sh && mysqladmin processlist
                  47 read,read,vio_read,select_max_min_finder_subselect ::cmp_str, select_max_min_finder_subselect::cmp_str,handle_on e_connecti on,pthread_mutexattr_init,??
                  (...)

                  +----------+------+-----------+------------+---------+------ ---+-------+------------------+
                  | Id | User | Host | db | Command | Time | State | Info |
                  +----------+------+-----------+------------+---------+------ ---+-------+------------------+
                  | 447 | cms | localhost | | Sleep | 3522200 | | |
                  | 448 | cms | localhost | | Sleep | 3522200 | | |
                  | 509 | cms | localhost | | Sleep | 0 | | |
                  ...
                  | 15624091 | cms | localhost | | Query | 0 | | show processlist |
                  +----------+------+-----------+------------+---------+------ ---+-------+------------------+

                  I did capture io and vm activity, but don't see anything unusual going on. This could also be because I'm not sure if my interpretation of vmstat is ok.

                  Then, the most interesting finding, is that it might nog be a query cache problem after all. If I profile the query under normal circumstances it takes most time in 'storing result in query cache':

                  | 1 | 1 | starting | 0.000049 | 0.000000 | 0.000044 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | |
                  | 1 | 2 | checking query cache for query | 0.009305 | 0.000000 | 0.000351 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1143
                  | 1 | 3 | Opening tables | 0.000077 | 0.000000 | 0.000072 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 2664
                  | 1 | 4 | System lock | 0.000013 | 0.000000 | 0.000013 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 153
                  | 1 | 5 | Table lock | 0.000101 | 0.000000 | 0.000100 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 163
                  | 1 | 6 | init | 0.000114 | 0.000000 | 0.000114 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 2275
                  | 1 | 7 | optimizing | 0.000051 | 0.000000 | 0.000051 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_select.cc | 759
                  | 1 | 8 | statistics | 0.000258 | 0.000000 | 0.000257 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_select.cc | 912
                  | 1 | 9 | preparing | 0.000053 | 0.000000 | 0.000053 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_select.cc | 922
                  | 1 | 10 | executing | 0.000020 | 0.000000 | 0.000020 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_select.cc | 1591
                  | 1 | 11 | Sorting result | 0.000009 | 0.000000 | 0.000009 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_select.cc | 1991
                  | 1 | 12 | Sending data | 0.000059 | 0.000000 | 0.000059 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_select.cc | 2115
                  | 1 | 13 | storing result in query cache | 6.269024 | 5.506759 | 0.111151 | 5879 | 1298 | 1 | 0 | 2427 | 4856 | 0 | 4 | 0 | query_cache_abort | sql_cache.cc | 691
                  | 1 | 14 | end | 0.000020 | 0.000016 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 2320
                  | 1 | 15 | end | 0.000009 | 0.000009 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 2322
                  | 1 | 16 | query end | 0.000009 | 0.000009 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5329
                  | 1 | 17 | freeing items | 0.000040 | 0.000041 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 6340
                  | 1 | 18 | closing tables | 0.000018 | 0.000017 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 2306
                  | 1 | 19 | logging slow query | 0.000008 | 0.000007 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | log_slow_statement | sql_parse.cc | 2364
                  | 1 | 20 | logging slow query | 0.000057 | 0.000057 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | log_slow_statement | sql_parse.cc | 2374
                  | 1 | 21 | cleaning up | 0.000016 | 0.000016 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 2329

                  But when bypassing the cache (using SQL_NO_CACHE) the same time is spent in 'Sending data':

                  | 1 | 1 | starting | 0.000029 | 0.000022 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | |
                  | 1 | 2 | checking query cache for query | 0.000232 | 0.000208 | 0.000025 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1143
                  | 1 | 3 | Opening tables | 0.000069 | 0.000061 | 0.000008 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 2664
                  | 1 | 4 | System lock | 0.000013 | 0.000011 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 153
                  | 1 | 5 | Table lock | 0.000020 | 0.000018 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 163
                  | 1 | 6 | init | 0.000106 | 0.000094 | 0.000012 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 2275
                  | 1 | 7 | optimizing | 0.000049 | 0.000044 | 0.000005 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_select.cc | 759
                  | 1 | 8 | statistics | 0.000245 | 0.000218 | 0.000027 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_select.cc | 912
                  | 1 | 9 | preparing | 0.000052 | 0.000046 | 0.000006 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_select.cc | 922
                  | 1 | 10 | executing | 0.000021 | 0.000018 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_select.cc | 1591
                  | 1 | 11 | Sorting result | 0.000013 | 0.000012 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_select.cc | 1991
                  | 1 | 12 | Sending data | 5.248548 | 5.575107 | 0.105959 | 6745 | 987 | 2 | 0 | 1960 | 3920 | 0 | 8 | 0 | exec | sql_select.cc | 2115
                  | 1 | 13 | end | 0.000018 | 0.000015 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 2320
                  | 1 | 14 | end | 0.000010 | 0.000009 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_select | sql_select.cc | 2322
                  | 1 | 15 | query end | 0.000009 | 0.000009 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5329
                  | 1 | 16 | freeing items | 0.000040 | 0.000039 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 6340
                  | 1 | 17 | closing tables | 0.000015 | 0.000014 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 2306
                  | 1 | 18 | logging slow query | 0.000007 | 0.000008 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | log_slow_statement | sql_parse.cc | 2364
                  | 1 | 19 | logging slow query | 0.000138 | 0.000138 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | log_slow_statement | sql_parse.cc | 2374
                  | 1 | 20 | cleaning up | 0.000016 | 0.000015 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 2329

                  I'm pretty convinced that the problem situation, where the query suddenly takes more than 200 secs, could also occur in the SQL_NO_CACHE query, and the time would be accounted to 'Sending data'.

                  So, here's my guess on the series of events:
                  thd_proc_info(thd, "Sending data") in exec() in sql_select.cc
                  -> ...
                  -> optionally thd_proc_info(thd, "storing result in query cache") in query_cache_abort() in sql_cache.cc
                  -> ...
                  -> something that sometimes takes forever
                  -> ...
                  -> thd_proc_info(thd, "end") in mysql_select() in sql_select.cc

                  Why query_cache_abort()? I don't know.

                  Maybe under certain loads the optimizer tries to use an execution plan that takes more than 200 secs? I'll keep investigating...

                  Comment


                  • #10
                    This,

                    47 read,read,vio_read,select_max_min_finder_subselect ::cmp_str, select_max_min_finder_subselect::cmp_str,handle_on e_connecti on,pthread_mutexattr_init,??

                    Is definitely not a sleeping connection ) There is a race condition between the stacktraces and the SHOW PROCESSLIST.

                    I would use oprofile at this point to find out where the time is being consumed.

                    Comment


                    • #11
                      Check this out:

                      # /usr/local/etc/rc.d/mysql-server startStarting mysql.# ./poormansprofiler.shwarning: Unable to get location for thread creation breakpoint: generic error 4 pthread_mutexattr_init,pthread_mutexattr_init,_pth read_cond_wait,pthread_cond_wait,trx_rollback_or_c lean_all_without_sess,trx_rollback_or_clean_all_wi thout_sess,trx_rollback_or_clean_all_without_sess, srv_master_thread,pthread_create,_ctx_start 1 pthread_testcancel,sigwait,signal_hand,pthread_mut exattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ setconcurrency,_nanosleep,nanosleep,select,trx_rol lback_or_clean_all_without_sess,srv_error_monitor_ thread,pthread_create,_ctx_start 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,_pthread_con d_wait,pthread_cond_wait,handle_manager,pthread_mu texattr_init,??,pthread_testcancel 1 pthread_testcancel,pthread_mutexattr_init,?? 1 pthread_mutexattr_init,pthread_mutexattr_init,_pth read_cond_wait,pthread_cond_wait,trx_rollback_or_c lean_all_without_sess,srv_master_thread,pthread_cr eate,_ctx_start 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_lock_t imeout_and_monitor_thread,pthread_create,_ctx_star t 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_error_ monitor_thread,pthread_create,_ctx_start 1 handle_segfault,??,??,??,??,my_str_malloc,__moddi3 ,?? 1# php -r 'mysql_connect("localhost","cms","cms123");sleep(5 0);' &[1] 2027# php -r 'mysql_connect("localhost","cms","cms123");sleep(5 0);' &[2] 2028# php -r 'mysql_connect("localhost","cms","cms123");sleep(5 0);' &[3] 2029# php -r 'mysql_connect("localhost","cms","cms123");sleep(5 0);' &[4] 2030# php -r 'mysql_connect("localhost","cms","cms123");sleep(5 0);' &[5] 2031# php -r 'mysql_connect("localhost","cms","cms123");sleep(5 0);' &[6] 2032# php -r 'mysql_connect("localhost","cms","cms123");sleep(5 0);' &[7] 2033# php -r 'mysql_connect("localhost","cms","cms123");sleep(5 0);' &[8] 2034# php -r 'mysql_connect("localhost","cms","cms123");sleep(5 0);' &[9] 2035# php -r 'mysql_connect("localhost","cms","cms123");sleep(5 0);' &[10] 2036# ./poormansprofiler.shwarning: Unable to get location for thread creation breakpoint: generic error 9 read,read,vio_read,select_max_min_finder_subselect ::cmp_str,select_max_min_finder_subselect::cmp_str ,handle_one_connection,pthread_mutexattr_init,?? 4 pthread_mutexattr_init,pthread_mutexattr_init,_pth read_cond_wait,pthread_cond_wait,trx_rollback_or_c lean_all_without_sess,trx_rollback_or_clean_all_wi thout_sess,trx_rollback_or_clean_all_without_sess, srv_master_thread,pthread_create,_ctx_start 1 select,select,handle_segfault,handle_segfault,??,? ?,??,??,my_str_malloc,__moddi3,?? 1 read,read,vio_read,select_max_min_finder_subselect ::cmp_str,select_max_min_finder_subselect::cmp_str ,handle_one_connection,pthread_mutexattr_init,??,p thread_testcancel 1 pthread_testcancel,sigwait,signal_hand,pthread_mut exattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,pthread_ setconcurrency,_nanosleep,nanosleep,select,trx_rol lback_or_clean_all_without_sess,srv_error_monitor_ thread,pthread_create,_ctx_start 1 pthread_testcancel,pthread_mutexattr_init,pthread_ mutexattr_init,pthread_mutexattr_init,_pthread_con d_wait,pthread_cond_wait,handle_manager,pthread_mu texattr_init,?? 1 pthread_testcancel,pthread_mutexattr_init,?? 1 pthread_mutexattr_init,pthread_mutexattr_init,_pth read_cond_wait,pthread_cond_wait,trx_rollback_or_c lean_all_without_sess,srv_master_thread,pthread_cr eate,_ctx_start 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_lock_t imeout_and_monitor_thread,pthread_create,_ctx_star t 1 pthread_mutexattr_init,_nanosleep,nanosleep,select ,trx_rollback_or_clean_all_without_sess,srv_error_ monitor_thread,pthread_create,_ctx_start 1


                      Weird, but perhaps not relevant:

                      # jobs[1] Done php -r mysql_connect("localhost","cms","cms123");sleep(50 );[2] Done php -r mysql_connect("localhost","cms","cms123");sleep(50 );[3] Done php -r mysql_connect("localhost","cms","cms123");sleep(50 );[4] Done php -r mysql_connect("localhost","cms","cms123");sleep(50 );[5] Done php -r mysql_connect("localhost","cms","cms123");sleep(50 );[6] Done php -r mysql_connect("localhost","cms","cms123");sleep(50 );[7] Done php -r mysql_connect("localhost","cms","cms123");sleep(50 );[8] + Done php -r mysql_connect("localhost","cms","cms123");sleep(50 );[9] + Done php -r mysql_connect("localhost","cms","cms123");sleep(50 );[10] + Done php -r mysql_connect("localhost","cms","cms123");sleep(50 );# ./poormansprofiler.shwarning: Unable to get location for thread creation breakpoint: generic errorError while reading shared library symbols:Cannot get thread info: invalid keyCannot get thread info: invalid key 1


                      Unfortunately oprofile is not available on FreeBSD. (

                      Comment

                      Working...
                      X