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

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.

[B]xaprb wrote on Fri, 26 March 2010 09:27[/B]
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?

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 |
±-----------------------------±---------------------+