# What is happening in "freeing items" state?

**URL:** <https://forums.percona.com/t/what-is-happening-in-freeing-items-state/1372>\
**Category:** Other MySQL® Questions\
**Created:** [March 25, 2010, 6:58pm UTC](https://forums.percona.com/t/what-is-happening-in-freeing-items-state/1372 "2010-03-25T18:58:13Z")\
**Posts on this page:** 4\
**Page:** 1

<div class="post-metadata">

**Author:** ![smunz](https://avatars.discourse-cdn.com/v4/letter/s/c77e96/32.png) [@smunz](https://forums.percona.com/u/smunz)\
**Post date:** [March 25, 2010, 6:58pm UTC](https://forums.percona.com/t/what-is-happening-in-freeing-items-state/1372/1 "2010-03-25T18:58:13Z")

</div>

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](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

---

<div class="post-metadata">

**Author:** ![xaprb](https://avatars.discourse-cdn.com/v4/letter/x/49beb7/32.png) [@xaprb](https://forums.percona.com/u/xaprb)\
**Post date:** [March 26, 2010, 7:57am UTC](https://forums.percona.com/t/what-is-happening-in-freeing-items-state/1372/2 "2010-03-26T07:57:53Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![smunz](https://avatars.discourse-cdn.com/v4/letter/s/c77e96/32.png) [@smunz](https://forums.percona.com/u/smunz)\
**Post date:** [March 26, 2010, 8:13am UTC](https://forums.percona.com/t/what-is-happening-in-freeing-items-state/1372/3 "2010-03-26T08:13:34Z")

</div>

| [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?

---

<div class="post-metadata">

**Author:** ![Kaydannik](https://avatars.discourse-cdn.com/v4/letter/k/8e7dd6/32.png) [@Kaydannik](https://forums.percona.com/u/Kaydannik)\
**Post date:** [August 19, 2010, 12:29pm UTC](https://forums.percona.com/t/what-is-happening-in-freeing-items-state/1372/4 "2010-08-19T12:29:57Z")

</div>

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