Re: Question related to MySQL and Threads and "Context_voluntary"

As you have stated, there is no IO activity during your test, so the disk config doesn't matter. The dataset uses fewer than 1000 pages in the InnoDB buffer cache.

>From the iostat output, the CPU usage for system time is huge (24% to
29%) while user time is low (0% to 1%).

I have benchmarks that do concurrent queries from multiple InnoDB tables on 4 CPU core servers. The tests are different in that they select all rows, so there is some network IO where yours only return 1 row. But the system time never exceeds 5% for 4, 8 or 16 concurrent clients.

Do you also get high system time from queries on MyISAM tables? InnoDB had some issues (mostly fixed) with multi-core servers, but it shouldn't be this bad. I am curious if your platform (MacOS X) might be part of the problem. My tests used Linux 2.6 on x86.

On 7/19/07, Mariella Petrini <mariellapetrini@yahoo.com> wrote:
>
> --- Mark Callaghan <mcallaghan@google.com> wrote:
>
> > On 7/19/07, Mariella Petrini
> > <mariellapetrini@yahoo.com> wrote:
> > > Hi,
> > >
> > >
> > > I have been working with MySQL 5.1.20 (64 bits
> > > compiled on Mac OS for MacPro Intel Xeon Quad-Core
> > > qith 2 processors and 8GB of RAM) and MySQL 5.0.41
> > (32
> > > bits).
> >
> > Does that mean the host has 8 cores?
> Correct
>
> > What is the disk configuration?
>
> Do you mean
> df -k
> Filesystem 1K-blocks Used Avail
> Capacity Mounted on
> /dev/disk1s2 488050672 157171460 330623212
> 32% /
> devfs 97 97 0
> 100% /dev
> fdesc 1 1 0
> 100% /dev
> <volfs> 512 512 0
> 100% /.vol
> /dev/disk0s2 488050672 70520 487980152
> 0% /Volumes/NotQuiteMaxDisk
> automount -nsl [206] 0 0 0
> 100% /Network
> automount -fstab [223] 0 0 0
> 100% /automount/Servers
> automount -static [223] 0 0 0
> 100% /automount/static
>
>
> or what type of RAID level is used ?
>
>
>
>
>
> >
> > >
> > > While running some bnchmarks of the select
> > statements
> > > (independently of the storage engine used, either
> > > InnoDB or MyISAM) I have noticed that
> > > the response time of a query degrades badly
> > (double
> > > degrades) as soon as another query is run.
> >
> > Is the server IO or CPU bound during the query?
> > vmstat and iostat will
> > help you determine that.
> >
> > >
> > > E.g. This is a case for a very simple query that
> > faces
> > > the problem.
> > >
> > > SELECT SQL_NO_CACHE count(DISTINCT user_id) as
> > > res_count FROM t1 WHERE (acc > 0 AND cat=34 AND
> > thr
> > > between 42 and 52) AND genre='SF';
> > >
> > > Using explain
> > >
> > >
> >
> +----+-------------+---------------------------+------+-------------------+---------------+---------+-------+-------+-------------+
> > > | id | select_type | table |
> > type
> > > | possible_keys | key | key_len |
> > ref
> > > | rows | Extra |
> > >
> >
> +----+-------------+---------------------------+------+-------------------+---------------+---------+-------+-------+-------------+
> > > | 1 | SIMPLE | t1 | ref | uag,genre_idx |
> > > genre_idx | 6 | const | 61324 | Using where
> > |
> > >
> >
> +----+-------------+---------------------------+------+-------------------+---------------+---------+-------+-------+-------------+
> > >
> > >
> > > show index from t1;
> > >
> >
> +---------------------------+------------+---------------+--------------+-----------------+-----------+-------------+----------+--------+------+------------+---------+
> > > | Table | Non_unique | Key_name |
> > Seq_in_index |
> > > Column_name | Collation | Cardinality |
> > Sub_part |
> > > Packed | Null | Index_type | Comment |
> > >
> >
> +---------------------------+------------+---------------+--------------+-----------------+-----------+-------------+----------+--------+------+------------+---------+
> > > | t1 | 1 | user_id_idx |
> > 1 |
> > > user_id | A | 178219 |
> > NULL |
> > > NULL | | BTREE | |
> > > | t1 | 1 | uag |
> > 1 |
> > > acc | A | 8 |
> > NULL |
> > > NULL | | BTREE | |
> > > | t1 | 1 | uag |
> > 2 |
> > > cat | A | 8 |
> > NULL |
> > > NULL | | BTREE | |
> > > | t1 | 1 | uag |
> > 3 |
> > > thr | A | 538 |
> > NULL |
> > > NULL | | BTREE | |
> > > | t1 | 1 | genre_idx |
> > 1 |
> > > genre | A | 6 |
> > NULL |
> > > NULL | | BTREE | |
> > >
> >
> +---------------------------+------------+---------------+--------------+-----------------+-----------+-------------+----------+--------+------+------------+---------+
> > >
> > >
> > > If there is only one query running the response
> > time
> > > is x, if there two queries running at the same
> > time
> > > the response time of each select is approximately
> > 2x,
> > > if there 3 queries running the response time is
> > > approximately 4x and if there are 4 queries
> > running
> > > concurrently the response time of each query is
> > > approximately 8x
> >
> > I would guess there is a network bottleneck, but the
> > query returns 1
> > row so that can't be it. My next guess is that all
> > of the queries are
> > competing for the same disk and the query is IO
> > bound.
>
> If there are no pageins/pageout all the data should be
> in memory,
> so in theory it shouldn't access the disk, except for
> flushing statistics.
>
>
>
>
> >
> > MyISAM and InnoDB have very different performance
> > characteristics.
> > 'show innodb status' provides useful counters on the
> > amount of IO done
> > by InnoDB.
>
> I have run both scenarios and same behavior. The only
> values that increase are the voluntary context
> switches and messages sent and received.
> The original testwas run on queries that involved
> hundreds of tables and same behavior.
>
> Before running show profiles I have been digging with
> show innodb status (all the settings appear to be
> optimum).
> 0 page swapping.
> The part that seems to change ignificantly is the one
> related to "SEMAPHORES"
>
> =====================================
> 12:19:53 INNODB MONITOR OUTPUT
> =====================================
> Per second averages calculated from the last 29
> seconds
> ----------
> SEMAPHORES
> ----------
> OS WAIT ARRAY INFO: reservation count 11015110, signal
> count 10903092
> Mutex spin waits 0, rounds 2384740514, OS waits 768529
> RW-shared spins 60927, OS waits 4778; RW-excl spins
> 90035, OS waits 5610
> ------------
> TRANSACTIONS
> ------------
> Trx id counter 0 58788
> Purge done for trx's n:o < 0 17405 undo n:o < 0 0
> History list length 2
> Total number of lock structs in row lock hash table 0
> LIST OF TRANSACTIONS FOR EACH SESSION:
> ---TRANSACTION 0 56323, not started, OS thread id
> 25524736
> MySQL thread id 1, query id 49381 localhost root
> show innodb status
> ---TRANSACTION 0 58787, ACTIVE 0 sec, OS thread id
> 25562112 fetching rows, thread declared inside InnoDB
> 393
> mysql tables in use 1, locked 0
> MySQL thread id 33, query id 49380 localhost root
> Sending data
> select SQL_NO_CACHE count(DISTINCT
> search_user_unique_innodb.user_id) as res_count FROM
> search_user_unique_innodb WHERE (account_type_id > 0
> AND category=34 AND age between 18 and 38) AND
> sexuality='SF'
> Trx read view will not see trx with id >= 0 58788,
> sees < 0 58784
> ---TRANSACTION 0 58786, ACTIVE 0 sec, OS thread id
> 25602048 fetching rows, thread declared inside InnoDB
> 289
> mysql tables in use 1, locked 0
> MySQL thread id 32, query id 49376 localhost root
> Sending data
> select SQL_NO_CACHE count(DISTINCT
> search_user_unique_innodb.user_id) as res_count FROM
> search_user_unique_innodb WHERE (account_type_id > 0
> AND category=34 AND age between 18 and 38) AND
> sexuality='SF'
> Trx read view will not see trx with id >= 0 58787,
> sees < 0 58783
> ---TRANSACTION 0 58785, ACTIVE 0 sec, OS thread id
> 25594368 fetching rows, thread declared inside InnoDB
> 285
> mysql tables in use 1, locked 0
> MySQL thread id 34, query id 49372 localhost root
> Sending data
> select SQL_NO_CACHE count(DISTINCT
> search_user_unique_innodb.user_id) as res_count FROM
> search_user_unique_innodb WHERE (account_type_id > 0
> AND category=34 AND age between 18 and 38) AND
> sexuality='SF'
> Trx read view will not see trx with id >= 0 58786,
> sees < 0 58782
> ---TRANSACTION 0 58784, ACTIVE 0 sec, OS thread id
> 25640960 fetching rows, thread declared inside InnoDB
> 371
> mysql tables in use 1, locked 0
> MySQL thread id 31, query id 49371 localhost root
> Sending data
> select SQL_NO_CACHE count(DISTINCT
> search_user_unique_innodb.user_id) as res_count FROM
> search_user_unique_innodb WHERE (account_type_id > 0
> AND category=34 AND age between 18 and 38) AND
> sexuality='SF'
> Trx read view will not see trx with id >= 0 58785,
> sees < 0 58782
> --------
> FILE I/O
> --------
> I/O thread 0 state: waiting for i/o request (insert
> buffer thread)
> I/O thread 1 state: waiting for i/o request (log
> thread)
> I/O thread 2 state: waiting for i/o request (read
> thread)
> I/O thread 3 state: waiting for i/o request (write
> thread)
> Pending normal aio reads: 0, aio writes: 0,
> ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
> Pending flushes (fsync) log: 0; buffer pool: 0
> 257 OS file reads, 279 OS file writes, 279 OS fsyncs
> 0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00
> fsyncs/s
> -------------------------------------
> INSERT BUFFER AND ADAPTIVE HASH INDEX
> -------------------------------------
> Ibuf: size 1, free list len 0, seg size 2,
> 0 inserts, 0 merged recs, 0 merges
> Hash table size 4425293, used cells 174319, node heap
> has 176 buffer(s)
> 154126.00 hash searches/s, 1068.31 non-hash searches/s
> ---
> LOG
> ---
> Log sequence number 0 3672793738
> Log flushed up to 0 3672793738
> Last checkpoint at 0 3672793738
> 0 pending log writes, 0 pending chkp writes
> 146 log i/o's done, 0.00 log i/o's/second
> ----------------------
> BUFFER POOL AND MEMORY
> ----------------------
> Total memory allocated 1243063488; in additional pool
> allocated 5369856
> Buffer pool size 65536
> Free buffers 64418
> Database pages 942
> Modified db pages 0
> Pending reads 0
> Pending writes: LRU 0, flush list 0, single page 0
> Pages read 942, created 0, written 69
> 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
> Buffer pool hit rate 1000 / 1000
> --------------
> ROW OPERATIONS
> --------------
> 4 queries inside InnoDB, 0 queries in queue
> 5 read views open inside InnoDB
> Main thread id 25334784, state: sleeping
> Number of rows inserted 0, updated 0, deleted 0, read
> 1041580444
> 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s,
> 155084.76 reads/s
> ----------------------------
> END OF INNODB MONITOR OUTPUT
> ============================
>
>
>
> ====================================
> 12:20:43 INNODB MONITOR OUTPUT
> =====================================
> Per second averages calculated from the last 50
> seconds
> ----------
> SEMAPHORES
> ----------
> OS WAIT ARRAY INFO: reservation count 11060403, signal
> count 10942334
> Mutex spin waits 0, rounds 2396569038, OS waits 790709
> RW-shared spins 62683, OS waits 4961; RW-excl spins
> 90969, OS waits 5788
> ------------
> TRANSACTIONS
> ------------
> Trx id counter 0 58917
> Purge done for trx's n:o < 0 17405 undo n:o < 0 0
> History list length 2
> Total number of lock structs in row lock hash table 0
> LIST OF TRANSACTIONS FOR EACH SESSION:
> ---TRANSACTION 0 56323, not started, OS thread id
> 25524736
> MySQL thread id 1, query id 49898 localhost root
> show innodb status
> ---TRANSACTION 0 58916, ACTIVE 0 sec, OS thread id
> 25594368, thread declared inside InnoDB 499
> mysql tables in use 1, locked 0
> MySQL thread id 34, query id 49897 localhost root
> Sending data
> select SQL_NO_CACHE count(DISTINCT
> search_user_unique_innodb.user_id) as res_count FROM
> search_user_unique_innodb WHERE (account_type_id > 0
> AND category=34 AND age between 18 and 38) AND
> sexuality='SF'
> Trx read view will not see trx with id >= 0 58917,
> sees < 0 58913
> ---TRANSACTION 0 58915, ACTIVE 1 sec, OS thread id
> 25562112 fetching rows, thread declared inside InnoDB
> 452
> mysql tables in use 1, locked 0
> MySQL thread id 33, query id 49893 localhost root
> Sending data
> select SQL_NO_CACHE count(DISTINCT
> search_user_unique_innodb.user_id) as res_count FROM
> search_user_unique_innodb WHERE (account_type_id > 0
> AND category=34 AND age between 18 and 38) AND
> sexuality='SF'
> Trx read view will not see trx with id >= 0 58916,
> sees < 0 58912
> ---TRANSACTION 0 58914, ACTIVE 1 sec, OS thread id
> 25602048 fetching rows, thread declared inside InnoDB
> 234
> mysql tables in use 1, locked 0
> MySQL thread id 32, query id 49889 localhost root
> Sending data
> select SQL_NO_CACHE count(DISTINCT
> search_user_unique_innodb.user_id) as res_count FROM
> search_user_unique_innodb WHERE (account_type_id > 0
> AND category=34 AND age between 18 and 38) AND
> sexuality='SF'
> Trx read view will not see trx with id >= 0 58915,
> sees < 0 58911
> ---TRANSACTION 0 58913, ACTIVE 2 sec, OS thread id
> 25640960 fetching rows, thread declared inside InnoDB
> 285
> mysql tables in use 1, locked 0
> MySQL thread id 31, query id 49885 localhost root
> Sending data
> select SQL_NO_CACHE count(DISTINCT
> search_user_unique_innodb.user_id) as res_count FROM
> search_user_unique_innodb WHERE (account_type_id > 0
> AND category=34 AND age between 18 and 38) AND
> sexuality='SF'
> Trx read view will not see trx with id >= 0 58914,
> sees < 0 58910
> --------
> FILE I/O
> --------
> I/O thread 0 state: waiting for i/o request (insert
> buffer thread)
> I/O thread 1 state: waiting for i/o request (log
> thread)
> I/O thread 2 state: waiting for i/o request (read
> thread)
> I/O thread 3 state: waiting for i/o request (write
> thread)
> Pending normal aio reads: 0, aio writes: 0,
> ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
> Pending flushes (fsync) log: 0; buffer pool: 0
> 257 OS file reads, 283 OS file writes, 283 OS fsyncs
> 0.00 reads/s, 0 avg bytes/read, 0.08 writes/s, 0.08
> fsyncs/s
> -------------------------------------
> INSERT BUFFER AND ADAPTIVE HASH INDEX
> -------------------------------------
> Ibuf: size 1, free list len 0, seg size 2,
> 0 inserts, 0 merged recs, 0 merges
> Hash table size 4425293, used cells 174319, node heap
> has 176 buffer(s)
> 153078.46 hash searches/s, 1059.88 non-hash searches/s
> ---
> LOG
> ---
> Log sequence number 0 3672793748
> Log flushed up to 0 3672793748
> Last checkpoint at 0 3672793748
> 0 pending log writes, 0 pending chkp writes
> 148 log i/o's done, 0.04 log i/o's/second
> ----------------------
> BUFFER POOL AND MEMORY
> ----------------------
> Total memory allocated 1243063488; in additional pool
> allocated 5369856
> Buffer pool size 65536
> Free buffers 64418
> Database pages 942
> Modified db pages 0
> Pending reads 0
> Pending writes: LRU 0, flush list 0, single page 0
> Pages read 942, created 0, written 70
> 0.00 reads/s, 0.00 creates/s, 0.02 writes/s
> Buffer pool hit rate 1000 / 1000
> --------------
> ROW OPERATIONS
> --------------
> 4 queries inside InnoDB, 0 queries in queue
> 5 read views open inside InnoDB
> Main thread id 25334784, state: sleeping
> Number of rows inserted 0, updated 0, deleted 0, read
> 1049282885
> 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s,
> 154045.74 reads/s
> ----------------------------
> END OF INNODB MONITOR OUTPUT
> ============================
>
>
>
>
>
>
> No pagein/pageout
> vmstat 1
>
>
> Mach Virtual Memory Statistics: (page size of 4096
> bytes, cache hits 61%)
> free active inac wire faults copy zerofill
> reactive pageins pageout
> 1668423 76092 228822 124188 3138376 51608
> 1788493 0 23632 0
> 1668424 75565 228821 124715 279 0
> 129 0 0 0
> 1668424 75565 228821 124715 220 0
> 128 0 0 0
> 1668420 76598 228825 123682 223 0
> 133 0 0 0
> 1668413 75565 228832 124715 186 0
> 94 0 0 0
> 1668442 75489 228801 124793 236 0
> 133 0 0 0
> 1668438 76599 228806 123682 221 0
> 132 0 0 0
> 1668431 75566 228813 124715 186 0
> 94 0 0 0
> 1668429 75566 228815 124715 222 0
> 131 0 0 0
> 1668427 76599 228817 123682 219 0
> 130 0 0 0
> 1668417 75566 228827 124715 189 0
> 97 0 0 0
> 1668423 76087 228820 124195 260 0
> 166 0 0 0
> 1668299 75567 228942 124717 916 0
> 802 0 0 0
> 1668296 75567 228945 124717 232 0
> 137 0 0 0
> 1668287 75567 228954 124717 198 0
> 101 0 0 0
> 1668272 75567 228969 124717 245 0
> 148 0 0 0
> 1668122 76599 229120 123684 378 0
> 283 0 0 0
> 1668113 76086 229129 124197 197 0
> 101 0 0 0
> 1668092 75567 229149 124717 312 0
> 198 0 0 0
> 1668092 75567 229149 124717 230 0
> 133 0 0 0
> 1668072 76087 229169 124197 146 0
> 69 0 0 0
>
>
>
>
>
> iostat 1
> disk1 disk0 cpu
> KB/t tps MB/s KB/t tps MB/s us sy id
> 16.83 6 0.09 10.38 0 0.00 0 1 98
> 0.00 0 0.00 0.00 0 0.00 1 28 72
> 0.00 0 0.00 0.00 0 0.00 1 27 73
> 0.00 0 0.00 0.00 0 0.00 0 27 72
> 0.00 0 0.00 0.00 0 0.00 0 25 75
> 0.00 0 0.00 0.00 0 0.00 1 25 74
> 0.00 0 0.00 0.00 0 0.00 1 26 73
> 0.00 0 0.00 0.00 0 0.00 1 27 73
> 0.00 0 0.00 0.00 0 0.00 0 26 74
> 0.00 0 0.00 0.00 0 0.00 0 27 73
> 0.00 0 0.00 0.00 0 0.00 1 26 74
> 0.00 0 0.00 0.00 0 0.00 0 27 73
> 0.00 0 0.00 0.00 0 0.00 0 26 74
> 0.00 0 0.00 0.00 0 0.00 0 27 73
> 0.00 0 0.00 0.00 0 0.00 1 27 73
> 0.00 0 0.00 0.00 0 0.00 0 27 72
> 0.00 0 0.00 0.00 0 0.00 1 25 74
> 0.00 0 0.00 0.00 0 0.00 0 26 73
> 0.00 0 0.00 0.00 0 0.00 0 26 74
> 21.67 20 0.42 0.00 0 0.00 1 27 72
> disk1 disk0 cpu
> KB/t tps MB/s KB/t tps MB/s us sy id
> 0.00 0 0.00 0.00 0 0.00 0 24 76
> 0.00 0 0.00 0.00 0 0.00 0 26 74
> 0.00 0 0.00 0.00 0 0.00 0 27 72
> 0.00 0 0.00 0.00 0 0.00 0 26 74
> 0.00 0 0.00 0.00 0 0.00 0 29 70
> 0.00 0 0.00 0.00 0 0.00 0 28 72
> 0.00 0 0.00 0.00 0 0.00 1 26 74
> 0.00 0 0.00 0.00 0 0.00 0 25 75
> 0.00 0 0.00 0.00 0 0.00 0 26 74
> 0.00 0 0.00 0.00 0 0.00 0 25 75
> 0.00 0 0.00 0.00 0 0.00 0 30 70
> 0.00 0 0.00 0.00 0 0.00 0 25 75
> 0.00 0 0.00 0.00 0 0.00 0 25 74
> 0.00 0 0.00 0.00 0 0.00 1 27 73
> 0.00 0 0.00 0.00 0 0.00 0 27 73
> 0.00 0 0.00 0.00 0 0.00 0 25 74
> 0.00 0 0.00 0.00 0 0.00 0 26 73
> 0.00 0 0.00 0.00 0 0.00 0 29 70
> 0.00 0 0.00 0.00 0 0.00 0 28 71
> 0.00 0 0.00 0.00 0 0.00 0 27 72
>
>
>
> Thanks in advance for your help,
>
> Mariella
>
>
> >
> > >
> > >
> > > I have been using "show profiling" in 5.0.x and I
> > have
> > > noticed that the amunt of increased time is due to
> > the
> > > step called "Sending data".
> > > Doing a little more digging, the variables that
> > > approximately double increase (during the
> > "Sending
> > > Data" step) are "Context_voluntary",
> > > "Messages__received" and "Messages_sent" .
> > >
> > > Question:
> > > Which could be the MySQL variables that could be
> > > changed and that could provide a major increase ?
> > >
> > > Could you please help ?
> > > Thanks in advance for your help,
> > >
> > > Mariella
> > >
> > >
> > >
> > >
> >
> ____________________________________________________________________________________
> > > Take the Internet to Go: Yahoo!Go puts the
> > Internet in your pocket: mail, news, photos & more.
> > > http://mobile.yahoo.com/go?refer=1GNXIC
> > >
> > > --
> > > MySQL Server Benchmarks Mailing List
> > > For list archives:
> > http://lists.mysql.com/benchmarks
> > > To unsubscribe:
> >
> http://lists.mysql.com/benchmarks?unsub=mcallaghan@google.com
> > >
> > >
> >
> >
> >
> > --
> > Mark Callaghan
> > mcallaghan@google.com
> >
>
>
>
>
> ____________________________________________________________________________________
> Yahoo! oneSearch: Finally, mobile search
> that gives answers, not web links.
> http://mobile.yahoo.com/mobileweb/onesearch?refer=1ONXIC
>

-- 
Mark Callaghan
mcallaghan@google.com

-- 
MySQL Server Benchmarks Mailing List
For list archives: 
http://lists.mysql.com/benchmarks
To unsubscribe:    
http://lists.mysql.com/benchmarks?unsub=lists@pantek.com