query_log output is mangled due to multithreadedness

[Henrik Ingo]

When enabling query_log plugin and directing 32 sysbench threads against it, I get output like below:

# start_ts=2012-05-18T10:56:32.046310
# session_id=12 query_id=11 rows_examined=1 rows_sent=1 tmp_tables=0 warnings=0
# execution_time=# start_ts=2012-05-18T10:56:32.045882
# session_id=12 query_id=11 rows_examined=1 rows_sent=1 tmp_tables=HERE id=0lock_time=
 warnings=0
# execution_time=0.002518 session_time=0.034174
# error=false
# schema="sbtest"
SELECT pad FROM sbtest1 WHERE id=20176010;
#
# start_ts=2012-05-18T10:56:32.046310
# session_id=12 query_id=11 rows_examined=1 rows_sent=1 tmp_tables=0 warnings=0
# execution_time=# start_ts=2012-05-18T10:56:32.045882
# session_id=12 query_id=11 rows_examined=1 rows_sent=1 tmp_tables=HERE id=0lock_time=
 warnings=0
# execution_time=0.002518 session_time=0.034174
# error=false
# schema="sbtest"
SELECT pad FROM sbtest1 WHERE id=20176010;
#
0.031333 lock_time=0.002518 session_time=0.034174
# error=false
# schema="sbtest"
SELECT pad FROM sbtest1 WHERE id=20176010;
#
....

It seems that output from multiple threads is mixed together.

[Daniel Nichter (daniel-nichter)]

Henrik,

Does logging_query have this problem too? Its code says:

    // a single write has a kernel thread lock, thus no need mutex guard this
    wrv= write(fd, msgbuf.c_str(), msgbuf.length());
    assert(wrv == msgbuf.length());

Whereas query_log does,

    _fh << "# start_ts=" << event->ts
    ...

which isn't thread-safe (and yes, that's my fault :-). If write() is indeed thread-safe, then it will be easy to make query_log use it like logginq_query.

[Henrik Ingo (hingo)]

I did not try logging_query. I'll let you know if I ever do. (This is on a work computer that I occasionally play with.)

[Stewart Smith (stewart)]

On Fri, 18 May 2012 14:12:21 -0000, Daniel Nichter <email address hidden> wrote:
> Does logging_query have this problem too? Its code says:
>
> // a single write has a kernel thread lock, thus no need mutex guard this
> wrv= write(fd, msgbuf.c_str(), msgbuf.length());
> assert(wrv == msgbuf.length());
>
> Whereas query_log does,
>
> _fh << "# start_ts=" << event->ts
> ...
>
> which isn't thread-safe (and yes, that's my fault :-). If write() is
> indeed thread-safe, then it will be easy to make query_log use it like
> logginq_query.

The write() will be safe, the << operator explicitly isn't.

--
Stewart Smith