GET 24/7 LIVE HELP NOW

Announcement

Announcement Module
Collapse
No announcement yet.

What is happening in "freeing items" state?

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

  • What is happening in "freeing items" state?

    Hello to everybody,

    i can't find any information about what is happening during the "freeing items" state when executing a query.
    The docs ( http://dev.mysql.com/doc/refman/5.1/en/general-thread-states .html) only contain this: "The thread has executed a command. This state is usually followed by cleaning up."
    Which parts of mysql could relate to a very long duration (up to 2 seconds) of this state?
    I am stuck with very slow write speeds accuring with different queries from time to time, for example:


    mysql> show profile all for query 14\G*************************** 1. row ***************************Status: startingDuration: 0.000057CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: NULLSource_file: NULLSource_line: NULL*************************** 2. row ***************************Status: checking permissionsDuration: 0.000006CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: check_accessSource_file: ../../sql/sql_parse.Source_line: 5161*************************** 3. row ***************************Status: Opening tablesDuration: 0.000021CPU_user: 0.001000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: open_tablesSource_file: ../../sql/sql_base.cSource_line: 4469*************************** 4. row ***************************Status: System lockDuration: 0.000005CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 1Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: mysql_lock_tablesSource_file: ../../sql/lock.ccSource_line: 258*************************** 5. row ***************************Status: Table lockDuration: 0.000009CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: mysql_lock_tablesSource_file: ../../sql/lock.ccSource_line: 269*************************** 6. row ***************************Status: initDuration: 0.000045CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: mysql_updateSource_file: ../../sql/sql_updateSource_line: 235*************************** 7. row ***************************Status: UpdatingDuration: 0.000131CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: mysql_updateSource_file: ../../sql/sql_updateSource_line: 535*************************** 8. row ***************************Status: endDuration: 0.000015CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: mysql_updateSource_file: ../../sql/sql_updateSource_line: 773*************************** 9. row ***************************Status: query endDuration: 0.000003CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: mysql_execute_commandSource_file: ../../sql/sql_parse.Source_line: 4923*************************** 10. row ***************************Status: freeing itemsDuration: 0.552723CPU_user: 0.001000CPU_system: 0.000000Context_voluntary: 395Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: mysql_parseSource_file: ../../sql/sql_parse.Source_line: 5950*************************** 11. row ***************************Status: logging slow queryDuration: 0.000009CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: log_slow_statementSource_file: ../../sql/sql_parse.Source_line: 1624*************************** 12. row ***************************Status: logging slow queryDuration: 0.000026CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: log_slow_statementSource_file: ../../sql/sql_parse.Source_line: 1634*************************** 13. row ***************************Status: cleaning upDuration: 0.000003CPU_user: 0.000000CPU_system: 0.000000Context_voluntary: 0Context_involuntary: 0Block_ops_in: 0Block_ops_out: 0Messages_sent: 0Messages_received: 0Page_faults_major: 0Page_faults_minor: 0Swaps: 0Source_function: dispatch_commandSource_file: ../../sql/sql_parse.Source_line: 159113 rows in set (0.00 sec)



    Any hint much appreciated!
    Sebastian

  • #2
    You'd have to examine the source code to find that out exactly. I'd start with using oprofile to try and see what's going on. That will be better than reading the source.

    Comment


    • #3
      xaprb wrote on Fri, 26 March 2010 09:27

      You'd have to examine the source code to find that out exactly. I'd start with using oprofile to try and see what's going on. That will be better than reading the source.


      Thanks for your advice. But oprofile gives me an "Kernel doesn't support oprofile"; i am running on OpenVZ, so this seem to be logical.

      Any advice on how to read the source? What to look for?

      Comment


      • #4
        Look for where thd->status is set to "freeing items" and just start reading ) Or try something like SystemTap (not sure if that's supported under OpenVZ). I'm suspicious now that you've told me you're in a VM. What's going on on the physical machine? VMs make performance optimization very hard, so good luck.

        Comment


        • #5
          We are having the same problems. Writes have a very large "freeing items" state that is 10-20 times as long as the other states. We have Query Cache turned off and are the master in a master-slave replication, though our slave does it too when we try running the queries on it.

          Comment


          • #6
            Did somebody solve this problem?
            We have the same problem:
            mysql1> SHOW PROFILE FOR QUERY 22;
            +----------------------+----------+
            | Status | Duration |
            +----------------------+----------+
            | starting | 0.000037 |
            | checking permissions | 0.000006 |
            | Opening tables | 0.000008 |
            | System lock | 0.000004 |
            | Table lock | 0.000003 |
            | init | 0.000016 |
            | update | 0.026193 |
            | end | 0.000008 |
            | query end | 0.000005 |
            | freeing items | 0.141789 |
            | logging slow query | 0.000007 |
            | cleaning up | 0.000005 |
            +----------------------+----------+

            5.1.47-rel11.2-log Percona Server
            master-slave

            mysql> show variables like '%buf%';
            +-----------------------------+-------------+
            | Variable_name | Value |
            +-----------------------------+-------------+
            | bulk_insert_buffer_size | 8388608 |
            | innodb_buffer_pool_size | 49392123904 |
            | innodb_change_buffering | inserts |
            | innodb_ibuf_accel_rate | 100 |
            | innodb_ibuf_active_contract | 1 |
            | innodb_ibuf_max_size | 24696045568 |
            | innodb_log_buffer_size | 8388608 |
            | join_buffer_size | 131072 |
            | key_buffer_size | 33554432 |
            | myisam_sort_buffer_size | 268435456 |
            | net_buffer_length | 16384 |
            | preload_buffer_size | 32768 |
            | read_buffer_size | 131072 |
            | read_rnd_buffer_size | 262144 |
            | sort_buffer_size | 2097144 |
            | sql_buffer_result | OFF |
            +-----------------------------+-------------+

            mysql> show variables like '%cache%';
            +------------------------------+----------------------+
            | Variable_name | Value |
            +------------------------------+----------------------+
            | binlog_cache_size | 32768 |
            | have_query_cache | YES |
            | key_cache_age_threshold | 300 |
            | key_cache_block_size | 1024 |
            | key_cache_division_limit | 100 |
            | max_binlog_cache_size | 18446744073709547520 |
            | query_cache_limit | 1048576 |
            | query_cache_min_res_unit | 4096 |
            | query_cache_size | 0 |
            | query_cache_strip_comments | OFF |
            | query_cache_type | ON |
            | query_cache_wlock_invalidate | OFF |
            | table_definition_cache | 256 |
            | table_open_cache | 4096 |
            | thread_cache_size | 30 |
            +------------------------------+----------------------+

            Comment

            Working...
            X