ASPECT #1

What catches my eye here is innodb_flush_method. You do not have it set. What does this imply? That you are letting the OS do some of InnoDB's dirty work.

If you set innodb_flush_method to O_DIRECT (which uses fsync()), then mysqld will shoulder the responsibility of flushing data and metadata changes to disk. This may make disk I/O increase slightly but it should remain constant and will provide better data consistency.

Without setting innodb_flush_method, the default value is really O_DSYNC using fdatasync(). This gives you asynchronous writes to disk. It appears faster at first, but when the OS has to do some syncing of the data from its viewpoint, it hits this massive wall of activity that is simply unavoidable.

[mysqld]
innodb_flush_method=O_DIRECT

I have a post about this from Mar 04, 2011: Clarification on MySQL innodb_flush_method variable

ASPECT #2 (Optional)

I also noticed that you have ibdata1 and ibdata2 split up in innodb_data_file_path. You also have innodb_file_per_table configured. This means no data and no indexes are in the ibdata files. In light of this, what other classes of information live in ibdata1 and ibdata2?

• MVCC (Multiversioning Concurrency Control) Data
  • Rollback Segments
  • Undo Space
• Table Metadata (Data Dictionary)
• Double Write Buffer (background writing to prevent reliance on OS caching)
• Insert Buffer (managing changes to non-unique secondary indexes)
• See the Pictorial Representation of ibdata1

You can collapse this to one ibdata1 file. Otherwise, you could find yourself with situation like:

• UNDO logs split across the files that are needed for the same transaction
• UNDO logs and Rollback Segments split across the files that are needed for the same transaction
• InnoDB Buffer Pool using different tablespace files for double write buffering and index updates.

These may not be as I/O impacting as flushing to disk but would could present fragmentation challenges to InnoDB during normal operation.

If you choose to collapse InnoDB Infrastructure to a single tablespace file, please see my StackOverflow post on how : Howto: Clean a mysql InnoDB storage engine?

ASPECT #3

Without knowing your hardware, I would just the same look over your storage.

• Using InnoDB on RAID10? you need to check out
  • Every Disk in the Arrays for I/O issues
  • RAID Controller for Latest Firmware updates
  • RAID Controller Battery-Backed Cache : https://dba.stackexchange.com/questions/33431/consequences-of-using-innodb-flush-method-o-direct-without-having-a-battery/33434#33434
• Using InnoDB on SATA? Please move to a SAN
• Using InnoDB on RAID5? You need a good psychiatrist : Is raid 5 suitable for a mysql installation?

Confirming what you already know, for future reference:

"The time to acquire the initial locks is not counted as execution time."

^{— http://dev.mysql.com/doc/refman/5.6/en/slow-query-log.html}

It stands to reason, at least to me, that a "slow query" is best defined as a query that is poorly-optimized and takes longer than it should even when run in isolation. It follows from that, that queries which only coincidentally take a long time to run because of circumstances unrelated to the query itself -- such as waiting for table locks -- should not be included in the slow query log.

I base this on two things: intuition, since the slow query log can also "log_queries_not_using_indexes" -- which is presumably also intended to catch bad optimization before the data set grows to the point that the queries actually turn into "slow" queries... and the fact that it doesn't seem to have been designed that way just because it was easier to implement or for any architectural limitation.

In sql/sql_class.h:

void update_server_status()
  {
    ulonglong end_utime_of_query= current_utime();
    if (end_utime_of_query > utime_after_lock + variables.long_query_time)
      server_status|= SERVER_QUERY_WAS_SLOW;
  }

If utime_after_lock were replaced with start_utime ... that should drive the behavior you are expecting. YMMV, but that's what it looks like from here, from a brief look into the source code.

Alternately, you could write a script in your favorite language to hold a connection to the server and execute SHOW PROCESSLIST every "n" seconds. The script would "remember" what each thread's Time value was from iteration to iteration, and could report execution times to you with the granularity of the polling interval when it found interesting patterns. When it sees an interesting query, it could switch to SHOW FULL PROCESSLIST to get the entire body of the query.

I would poll my servers for their processlist (not "full") at 1 second intervals -- yes, in production -- and display the number of threads and the current longest-running query on my real-time status dashboard and have never seen evidence of an ill-effect from this.