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