Not the answer you need?
Register and ask your own question!
Many Forum changes were implemented on Tue 22 Sep. Read about new Ranks, Scoring, and Reactions.
Email [email protected] for any comments or concerns.

What is happening in "freeing items" state?

smunzsmunz EntrantInactive User Role Beginner
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)</pre>



Any hint much appreciated!
Sebastian

Comments

  • xaprbxaprb Mentor Inactive User Role Beginner
    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.
  • smunzsmunz Entrant Inactive User Role Beginner
    <table border="0" align="center" width="90%" cellpadding="3" cellspacing="1"><tr><td class="SmallText">xaprb wrote on Fri, 26 March 2010 09:27</td></tr><tr><td class="quote">
    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.
    </td></tr></table>

    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?
  • KaydannikKaydannik Entrant Current User Role Beginner
    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 |
    +
    +
    +
Sign In or Register to comment.

MySQL, InnoDB, MariaDB and MongoDB are trademarks of their respective owners.
Copyright ©2005 - 2020 Percona LLC. All rights reserved.