Why UPDATE queries using primary key can be slow?
Pavel Shevaev
strange entries in the slow query log. I don't understand why this can
be happening and if someone could enlighten me I'd be very grateful. I
hope it's OK to ask such questions on this list(please tell me if
not).
I see slow UPDATE queries using the primary key which may run 1-3
seconds. The table 'player' used in UPDATE queries has the following
schema:
Create Table: CREATE TABLE `player` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`portal_id` bigint(20) unsigned NOT NULL DEFAULT '0',
`proto_id` int(10) NOT NULL DEFAULT '0',
`name` varchar(32) NOT NULL DEFAULT '',
`energy` int(10) NOT NULL DEFAULT '0',
`sex` int(1) NOT NULL DEFAULT '0',
`money` int(10) NOT NULL DEFAULT '0',
`tile_x` int(10) NOT NULL DEFAULT '0',
`tile_y` int(10) NOT NULL DEFAULT '0',
`last_active_time` int(10) NOT NULL DEFAULT '0',
`last_login_time` int(10) unsigned NOT NULL DEFAULT '0',
`last_energy_regen_time` int(10) NOT NULL DEFAULT '0',
`rating` int(10) NOT NULL DEFAULT '0',
`level` int(10) NOT NULL DEFAULT '0',
`food` int(10) NOT NULL DEFAULT '0',
`wood` int(10) NOT NULL DEFAULT '0',
`tutorial_step` int(10) NOT NULL DEFAULT '0',
`energy_max` int(10) NOT NULL DEFAULT '15',
`unlocked_proto` varbinary(20000) NOT NULL DEFAULT '',
`shoppings` varbinary(40000) NOT NULL DEFAULT '',
`host_id` int(10) unsigned NOT NULL DEFAULT '0',
`last_bill_id` int(10) unsigned NOT NULL DEFAULT '0',
`reg_time` int(11) unsigned NOT NULL DEFAULT '0',
`customize` varchar(255) NOT NULL DEFAULT '',
PRIMARY KEY (`id`),
KEY `portal_id` (`portal_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;
Here are some entries from the slow log:
# Thread_id: 1186152 Schema: castaway Last_errno: 0 Killed: 0
# Query_time: 2.018585 Lock_time: 0.000040 Rows_sent: 0
Rows_examined: 1 Rows_affected: 1 Rows_read: 1
# Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 2E0F4D53
SET timestamp=1299422826;
UPDATE player SET energy=1 WHERE id=228629;
# Thread_id: 1186148 Schema: castaway Last_errno: 0 Killed: 0
# Query_time: 2.308575 Lock_time: 0.000037 Rows_sent: 0
Rows_examined: 1 Rows_affected: 1 Rows_read: 1
# Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 2E0F4D44
SET timestamp=1299422826;
UPDATE player SET money=4656,rating=465,energy=3 WHERE id=232158;
# Thread_id: 1186173 Schema: castaway Last_errno: 0 Killed: 0
# Query_time: 1.951154 Lock_time: 0.000076 Rows_sent: 0
Rows_examined: 1 Rows_affected: 1 Rows_read: 1
# Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 2E0F4DAF
SET timestamp=1299422826;
UPDATE player SET
money=2500,rating=10,food=50,energy=9,tutorial_step=3 WHERE id=238827;
The server is IMHO not IO bound, here is a typical iostat output
during slow queries:
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s
avgrq-sz avgqu-sz await svctm %util
sda 0.00 10.60 23.20 332.80 158.40 1140.60
7.30 0.16 0.46 0.38 13.40
sda 0.00 10.20 22.60 313.00 157.60 928.20
6.47 0.19 0.56 0.47 15.80
sda 0.00 9.40 26.20 352.00 198.40 1271.70
7.77 0.18 0.48 0.34 13.00
sda 0.00 10.20 24.60 312.20 194.40 1001.30
7.10 0.21 0.59 0.42 14.20
The server load average is in range from 2.0 to 2.1 but dstat shows
nothing unusual, here is a typical output:
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read writ| recv send| in out | int csw
11 2 83 2 0 1| 513k 2903k| 0 0 | 0 0 | 11k 22k
9 2 86 1 0 1| 276k 844k| 0 0 | 0 0 | 12k 14k
12 2 84 1 0 2| 236k 1224k|1021k 24M| 0 0 | 11k 17k
13 1 83 1 0 1| 136k 749k| 0 0 | 0 0 | 11k 14k
12 3 83 1 0 1| 368k 2887k| 960k 21M| 0 0 | 11k 17k
12 2 83 1 0 1| 180k 1114k| 0 0 | 0 0 | 12k 17k
I also tried running the oprofile but for some reason it invoked the
kernel panic and I'm not that brave to try it again on the production
server :)
I tried to configure the Percona server so that it stores as much as
possible data in memory. And innotop shows there is still plenty free
space in the buffer pool:
___________________________ Buffer Pool ___________________________
Size Free Bufs Pages Dirty Pages Hit Rate Memory Add'l Pool
1.12M 890338 275091 47313 18.46G 0
_____________________ Page Statistics _____________________
Reads Writes Created Reads/Sec Writes/Sec Creates/Sec
269902 89058 5189 7.30 5.20 0.10
______________________ Insert Buffers ______________________
Inserts Merged Recs Merges Size Free List Len Seg. Size
27 27 27 1 0 2
_________________ Adaptive Hash Index __________________
Size Cells Used Node Heap Bufs Hash/Sec Non-Hash/Sec
373.16 1193.58
And here's the query list from innotop:
When Load QPS Slow Se/In/Up/De% QCacheHit KCacheHit BpsIn
BpsOut
Now 0.00 638.27 0 47/16/ 8/ 2 0.00% 100.00%
101.31k 583.77k
Total 0.00 593.84 17.88k 45/17/ 8/ 2 0.00% 94.23%
90.28k 535.85k
Here's also my my.cnf:
[mysqld]
user = mysql
socket = /var/run/mysqld/mysqld.sock
pid-file = /var/run/mysqld/mysqld.pid
port = 3306
basedir = /usr
datadir = /var/lib/mysql
tmpdir = /tmp
skip-external-locking
skip-name-resolve
old_passwords = 1
key_buffer = 16M
max_allowed_packet = 16M
thread_stack = 192K
thread_cache_size = 8
myisam-recover = BACKUP
max_connections = 10000
query_cache_type = 0
query_cache_size = 0
log_error = /var/log/mysql/error.log
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 1
server-id = 10
log_bin = mysql-bin
relay_log = mysql-relay-bin
sync_binlog = 1
expire_logs_days = 1
max_binlog_size = 100M
innodb_buffer_pool_size = 18G
innodb_data_file_path = ibdata1:10M:autoextend
innodb_file_per_table = true
innodb_flush_log_at_trx_commit = 2
innodb_log_buffer_size = 8M
innodb_log_files_in_group = 2
innodb_log_file_size = 2000M
innodb_thread_concurrency = 0
innodb_flush_method = O_DIRECT
innodb_read_io_threads = 2
innodb_write_io_threads = 2
innodb_io_capacity = 200
innodb_use_purge_thread = 1
innodb_adaptive_checkpoint = estimate
Thanks in advance for any ideas why this can be happening...
--
Best regards, Pavel
Baron Schwartz
> # Thread_id: 1186152 Schema: castaway Last_errno: 0 Killed: 0
> # Query_time: 2.018585 Lock_time: 0.000040 Rows_sent: 0
> Rows_examined: 1 Rows_affected: 1 Rows_read: 1
> # Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
> # InnoDB_trx_id: 2E0F4D53
> SET timestamp=1299422826;
> UPDATE player SET energy=1 WHERE id=228629;
Please set log_slow_verbosity to include 'innodb' so you can see more
information about the query execution, e.g.
set global log_slow_verbosity="microtime,innodb,query_plan";
I am going to file a bug about the above output. The InnoDB
transaction ID shouldn't be included in the log if log_slow_verbosity
doesn't include "innodb", and the temp table information shouldn't be
included unless log_slow_verbosity includes "query_plan".
Pavel Shevaev
> Pavel,
>
>> # Thread_id: 1186152 Schema: castaway Last_errno: 0 Killed: 0
>> # Query_time: 2.018585 Lock_time: 0.000040 Rows_sent: 0
>> Rows_examined: 1 Rows_affected: 1 Rows_read: 1
>> # Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
>> # InnoDB_trx_id: 2E0F4D53
>> SET timestamp=1299422826;
>> UPDATE player SET energy=1 WHERE id=228629;
>
> Please set log_slow_verbosity to include 'innodb' so you can see more
> information about the query execution, e.g.
>
> set global log_slow_verbosity="microtime,innodb,query_plan";
Thanks for the tip. Here is what I see in the log now(a couple of
typical entries):
# User@Host: castaway[castaway] @ localhost []
# Thread_id: 407335 Schema: castaway Last_errno: 0 Killed: 0
# Query_time: 1.137063 Lock_time: 0.000038 Rows_sent: 0
Rows_examined: 1 Rows_affected: 1 Rows_read: 1
# Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 2E72C662
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 5
SET timestamp=1299445241;
UPDATE player SET money=6616,rating=2780,energy=12 WHERE id=1575;
# User@Host: castaway[castaway] @ localhost []
# Thread_id: 407330 Schema: castaway Last_errno: 0 Killed: 0
# Query_time: 1.299271 Lock_time: 0.000042 Rows_sent: 0
Rows_examined: 1 Rows_affected: 1 Rows_read: 1
# Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 2E72C64E
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 5
SET timestamp=1299445241;
UPDATE player SET money=16627,rating=1293,wood=2422,energy=3 WHERE id=153059;
--
Best regards, Pavel
Pavel Shevaev
it has about 250k records with total size about 130Mb
--
Best regards, Pavel
Peter Zaitsev
It looks like the stall happens somewhere which is not reported by this basic statistics,
Can you enable profiling_server=1 variable it will give you even more stats:
# Time: 110306 16:11:07
# User@Host: root[root] @ localhost []
# Thread_id: 102 Schema: test Last_errno: 0 Killed: 0
# Query_time: 0.000010 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1 Rows_affected: 0 Rows_read: 18446744073709551613
# Bytes_sent: 10130 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: F58A00
# Profile_starting: 0.000023 Profile_starting_cpu: 0.000022 Profile_logging_slow_query: 0.000005 Profile_logging_slow_query_cpu: 0.000005
# Profile_total: 0.000028 Profile_total_cpu: 0.000027
SET timestamp=1299456667;
We should see in which stage this time comes from.
--
You received this message because you are subscribed to the Google Groups "Percona Discussion" group.
To post to this group, send email to percona-d...@googlegroups.com.
To unsubscribe from this group, send email to percona-discuss...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/percona-discussion?hl=en.
--
Peter Zaitsev, CEO, Percona Inc.
Tel: +1 888 401 3401 ext 501 Skype: peter_zaitsev
24/7 Emergency Line +1 888 401 3401 ext 911
Looking for MySQL Support ?
http://www.percona.com/support/
Pavel Shevaev
> stats:
Sure, here is some output after this:
# User@Host: castaway[castaway] @ localhost []
# Thread_id: 1181644 Schema: castaway Last_errno: 0 Killed: 0
# Query_time: 1.481238 Lock_time: 0.000039 Rows_sent: 0
Rows_examined: 1 Rows_affected: 1 Rows_read: 1
# Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 2ED216F9
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 7
# Profile_starting: 0.000029 Profile_starting_cpu: 0.000028
Profile_checking_permissions: 0.000005
Profile_checking_permissions_cpu: 0.000004 Profile_Opening_tables:
0.000006 Profile_Opening_tables_cpu: 0.000006 Profile_System_lock:
0.000002 Profile_System_lock_cpu: 0.000002 Profile_Table_lock:
0.000003 Profile_Table_lock_cpu: 0.000002 Profile_init: 0.000053
Profile_init_cpu: 0.000053 Profile_Updating: 1.400018
Profile_Updating_cpu: 0.000280 Profile_end: 0.000017 Profile_end_cpu:
0.000016 Profile_query_end: 0.000005 Profile_query_end_cpu: 0.000004
Profile_freeing_items: 0.081107 Profile_freeing_items_cpu: 0.000295
Profile_logging_slow_query: 0.000002 Profile_logging_slow_query_cpu:
0.000002
# Profile_total: 1.481244 Profile_total_cpu: 0.000691
SET timestamp=1299474081;
UPDATE player SET money=6787,rating=3263,energy=9 WHERE id=29404;
# User@Host: castaway[castaway] @ localhost []
# Thread_id: 1181605 Schema: castaway Last_errno: 0 Killed: 0
# Query_time: 2.272329 Lock_time: 0.000043 Rows_sent: 0
Rows_examined: 1 Rows_affected: 1 Rows_read: 1
# Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 2ED2164A
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 7
# Profile_starting: 0.000030 Profile_starting_cpu: 0.000030
Profile_checking_permissions: 0.000005
Profile_checking_permissions_cpu: 0.000004 Profile_Opening_tables:
0.000008 Profile_Opening_tables_cpu: 0.000008 Profile_System_lock:
0.000002 Profile_System_lock_cpu: 0.000002 Profile_Table_lock:
0.000003 Profile_Table_lock_cpu: 0.000003 Profile_init: 0.000062
Profile_init_cpu: 0.000062 Profile_Updating: 0.000100
Profile_Updating_cpu: 0.000099 Profile_end: 2.180680 Profile_end_cpu:
0.000027 Profile_query_end: 0.000004 Profile_query_end_cpu: 0.000004
Profile_freeing_items: 0.091440 Profile_freeing_items_cpu: 0.000281
Profile_logging_slow_query: 0.000003 Profile_logging_slow_query_cpu:
0.000002
# Profile_total: 2.272336 Profile_total_cpu: 0.000522
SET timestamp=1299474081;
UPDATE player SET money=105,rating=26,energy=4 WHERE id=168625;
--
Best regards, Pavel
petya
This seems really intresting. I wonder if the reason is the relatively
huge records you got. Is anything else slow? From this log, you are not
waiting on locks. Is there production traffic on the server while you
are testing?
I can't think anything but huge records. Can you test with smaller
records? Here is a stored procedure for you to load 250k records in a
smaller table.
DROP PROCEDURE IF EXISTS fill_test_table;
DELIMITER //
CREATE PROCEDURE fill_test_table()
BEGIN
DECLARE v_counter INT DEFAULT 0;
SET SESSION autocommit = 0;
REPEAT
SET v_counter = v_counter + 1;
INSERT INTO t VALUES (v_counter,v_counter);
IF v_counter MOD 1000 = 0 THEN
COMMIT;
END IF;
UNTIL v_counter > 250000 END REPEAT;
END
//
DELIMITER ;
Here is the table for that:
create table t (id int auto_increment, a int, primary key(id))
engine=innodb;
To load the data use CALL fill_test_table(). Use a separate schema.
Then do updates on a based on the primary key (id). If this is slow too,
I would look for storage level issues. Can be that that you are on
raid5, and for such a small update, you are writing a whole stripe, and
you have got relatively large stripe size.
Peter Boros
petya
I changed my mind:). Most likely it is not storage, since redo logs
should only contain page modifications, which is small and sequential
io, and writing of the tablespace should be cached by the buffer pool.
However, I am curious about the other stuff, like comparing the update
time to a much more narrow table.
Peter Boros
Pavel Shevaev
> only contain page modifications, which is small and sequential io, and
> writing of the tablespace should be cached by the buffer pool. However, I am
> curious about the other stuff, like comparing the update time to a much more
> narrow table.
I created the test table, filled it with your stored procedure and
made a quick testing script as follows:
<?php
$link = mysqli_connect('localhost', 'root', 'xxxxx');
mysqli_select_db($link, 'bench');
for($i=0;$i<10000;++$i)
{
$idx = mt_rand(0, 250000);
$t1 = microtime(true);
if(mysqli_query($link, "UPDATE t set a=$idx WHERE id=$idx") === false)
throw new Exception("Ooops");
$ts = microtime(true)-$t1;
if($ts > 0.1)
echo $i . "($idx)# " . $ts . "\n";
usleep(1000);
}
?>
Running it shows the following result:
$ php test.php
3760(29046)# 0.14032816886902
4895(94735)# 0.12281394004822
8945(194271)# 0.14129304885864
9998(19933)# 0.2691822052002
Hope this helps...
--
Best regards, Pavel
Pavel Shevaev
> Hi,
>
> This seems really intresting. I wonder if the reason is the relatively huge
> records you got. Is anything else slow?
Well there are other slow queries but they are INSERT related. I was
going to investigate why they are slow as well once I know the reason
why UPDATE queries are slow(which I believe is easier to pinpoint).
> From this log, you are not waiting
> on locks. Is there production traffic on the server while you are testing?
Yep, it's a production server where about 2k players are online...
> Can be that that you are on raid5, and
> for such a small update, you are writing a whole stripe, and you have got
> relatively large stripe size.
Well, what I know for sure is the fact the server is using raid10 on
"3ware Inc 9690SA SAS/SATA-II RAID PCIe" controller...
--
Best regards, Pavel
petya
So, this is fast. Can you repeat your benchmark on a copy of your
table? We will get comparable results this way.
Peter Boros
Pavel Shevaev
> Hi,
>
> So, this is fast. Can you repeat your benchmark on a copy of your table? We
> will get comparable results this way.
Sure, I copied the table and changed the bench script a bit, here it is:
<?php
$link = mysqli_connect('localhost', 'root', 'xxxxxx');
mysqli_select_db($link, 'bench');
for($i=0;$i<10000;++$i)
{
$idx = mt_rand(0, 250000);
$t1 = microtime(true);
if(mysqli_query($link, "UPDATE player set energy=$idx, money=$idx,
rating=$idx WHERE id=$idx") === false)
throw new Exception("Ooops");
$ts = microtime(true)-$t1;
if($ts > 0.1)
echo $i . "($idx)# " . $ts . "\n";
usleep(1000);
}
?>
$ php test.php
715(193462)# 0.2290940284729
3278(127785)# 0.29388880729675
3279(36796)# 0.1245059967041
3280(155162)# 0.16235399246216
3996(54195)# 0.11022305488586
5013(146955)# 0.11410117149353
6042(20921)# 0.10275101661682
7047(81289)# 0.13876104354858
7983(210593)# 0.10232901573181
9989(90376)# 0.15921187400818
--
Best regards, Pavel
petya
So, this is not as slow as your regular updates. Did you run this on
your production machine, just used an other table? If inserts are slow
too, we can say that writes are slow. Maybe we should check around
checkpointing, but if you ran this on the same server, it wouldn't
explain what we see here.
Peter Boros
Pavel Shevaev
> production machine, just used an other table?
Yep, the same production machine, using different database.
--
Best regards, Pavel
Peter Zaitsev
Now we can see it is in "Updating" stage but yet Innodb usual suspects for delay such as row level lock
waits or IO do not show up. So it is something interesting..
I suggest you to check with PMP http://poormansprofiler.org/ at the time when problem happens to see where
waits happen.
Justin Swanhart
Can you also provide a 'SHOW SESSION STATUS' before and after you run the UPDATE query?
--Justin
--
You received this message because you are subscribed to the Google Groups "Percona Discussion" group.
To post to this group, send email to percona-d...@googlegroups.com.
To unsubscribe from this group, send email to percona-discuss...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/percona-discussion?hl=en.
--
Justin Swanhart, Principal Consultant, Percona Inc.
Bay Area, USA (PDT, GMT -7)
+1 888 401 3401 | 24x7 Help x911
Our Services:
http://www.percona.com/services/
We also offer training!
Percona offers regularly scheduled public training events and private on-site training too.
http://www.percona.com/training/
Pavel Shevaev
> Nice....
>
> Now we can see it is in "Updating" stage but yet Innodb usual suspects for
> delay such as row level lock
> waits or IO do not show up. So it is something interesting..
>
> I suggest you to check with PMP http://poormansprofiler.org/ at the time
> when problem happens to see where
> waits happen.
>
Thanks, I'll try this one. I'm not sure if it will be possible to run
it in the right moment though. BTW, oprofile should reveal similar
information, right? (however, as I wrote in the first post, I'm scared
to run it since it made the kernel panic)
--
Best regards, Pavel
Peter Zaitsev
No. Oprofile looks at CPU usage and in your case we can see no significant CPU was spent.
Pavel Shevaev
> Pavel,
>
> No. Oprofile looks at CPU usage and in your case we can see no significant
> CPU was spent.
Thanks for clarification. The bad news is...the server is down because
of the faulty raid controller :( I'm waiting for a replacement...
Maybe it was this junky piece of hardware which caused the stalls?
I'll report later once I have the server back online...
--
Best regards, Pavel
Pavel Shevaev
# Thread_id: 48532094 Schema: od_castw Last_errno: 0 Killed: 0
# Query_time: 4.758034 Lock_time: 0.000030 Rows_sent: 0
Rows_examined: 1 Rows_affected: 1 Rows_read: 1
# Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 17E9D499
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 7
# Profile_starting: 0.000018 Profile_starting_cpu: 0.000000
Profile_checking_permissions: 0.000004
Profile_checking_permissions_cpu: 0.000000 Profile_Opening_tables:
0.000007 Profile_Opening_tables_cpu: 0.000000 Profile_System_lock:
0.000002 Profile_System_lock_cpu: 0.000000 Profile_Table_lock:
0.000003 Profile_Table_lock_cpu: 0.000000 Profile_init: 0.000025
Profile_init_cpu: 0.000000 Profile_Updating: 4.727162
Profile_Updating_cpu: 0.000000 Profile_end: 0.000015 Profile_end_cpu:
0.000000 Profile_query_end: 0.000004 Profile_query_end_cpu: 0.000000
Profile_freeing_items: 0.030797 Profile_freeing_items_cpu: 0.000000
Profile_logging_slow_query: 0.000003 Profile_logging_slow_query_cpu:
0.000000
# Profile_total: 4.758040 Profile_total_cpu: 0.000000
SET timestamp=1299785313;
UPDATE player SET rmoney=6,rating=22 WHERE id=503173;
# Thread_id: 48532124 Schema: od_castw Last_errno: 0 Killed: 0
# Query_time: 1.027639 Lock_time: 0.000054 Rows_sent: 0
Rows_examined: 1 Rows_affected: 1 Rows_read: 1
# Bytes_sent: 52 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 17E9D500
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 9
# Profile_starting: 0.000019 Profile_starting_cpu: 0.000000
Profile_checking_permissions: 0.000005
Profile_checking_permissions_cpu: 0.000000 Profile_Opening_tables:
0.000029 Profile_Opening_tables_cpu: 0.000000 Profile_System_lock:
0.000003 Profile_System_lock_cpu: 0.000000 Profile_Table_lock:
0.000003 Profile_Table_lock_cpu: 0.000000 Profile_init: 0.000044
Profile_init_cpu: 0.000000 Profile_Updating: 0.996541
Profile_Updating_cpu: 0.000000 Profile_end: 0.000012 Profile_end_cpu:
0.000000 Profile_query_end: 0.000004 Profile_query_end_cpu: 0.000000
Profile_freeing_items: 0.030984 Profile_freeing_items_cpu: 0.000000
Profile_logging_slow_query: 0.000003 Profile_logging_slow_query_cpu:
0.000000
# Profile_total: 1.027646 Profile_total_cpu: 0.000000
SET timestamp=1299785313;
UPDATE player SET rating=259 WHERE id=332607;
Looks like Profile_Updating and Profile_freeing_items are the slowest,
how can I fix that?
--
Best regards, Pavel
林晓斌
--
Best regards, Pavel
Pavel Shevaev
> Do the slow queries appear every seconds, or appear "randomly"?
I'd rather say they appear every some seconds. Sometimes every 1-2
seconds, sometimes in 10 or 30 seconds...
>
> If they do not appear every second, I propose that you can pay attention to
> the status value of "Innodb_buffer_pool_pages_dirty", and get the conclusion
> :
>
> Does the Innodb_buffer_pool_pages_dirty value decrease almost at the
> same time of appearing slow queries ?
I tried watching in tmux Innodb_buffer_pool_pages_dirty via innotop in
one window and slow query log entries in another - I could not see any
clear relation between them. For example, at some moment I clearly see
that Innodb_buffer_pool_pages_free is decreasing and there are new
slow log entries, at another moment Innodb_buffer_pool_pages_free is
decreasing again but there are no slow logs...
--
Best regards, Pavel
Vadim Tkachenko
Are you using Percona Server ?
Do you see output like this in SHOW INNODB STATUS ?
---
LOG
---
Log sequence number 121614156380
Log flushed up to 121614017661
Last checkpoint at 121589412364
Max checkpoint age 6957135914
Checkpoint age target 6739725417
Modified age 24721672
Checkpoint age 24744016
If so, please setup script to take "SHOW INNODB STATUS" each to sec,
and then it would be interesting to take look in graph with
"Checkpoint age" value
and how it is close to "Checkpoint age target".
> --
> You received this message because you are subscribed to the Google Groups "Percona Discussion" group.
> To post to this group, send email to percona-d...@googlegroups.com.
> To unsubscribe from this group, send email to percona-discuss...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/percona-discussion?hl=en.
>
>
--
Vadim Tkachenko, CTO, Percona Inc.
Phone +1-888-401-3403, Skype: vadimtk153
Schedule meeting: http://tungle.me/VadimTkachenko
Pavel Shevaev
> Pavel,
>
> Are you using Percona Server ?
Yep
>
> Do you see output like this in SHOW INNODB STATUS ?
> ---
> LOG
> ---
> Log sequence number 121614156380
> Log flushed up to 121614017661
> Last checkpoint at 121589412364
> Max checkpoint age 6957135914
> Checkpoint age target 6739725417
> Modified age 24721672
> Checkpoint age 24744016
>
> If so, please setup script to take "SHOW INNODB STATUS" each to sec,
> and then it would be interesting to take look in graph with
> "Checkpoint age" value
> and how it is close to "Checkpoint age target".
Yep, sure, running for 60 seconds enough?
---------------
1 # Checkpoint age target 3290529037 VS Checkpoint age 548267259
---------------
2 # Checkpoint age target 3290529037 VS Checkpoint age 548307162
---------------
3 # Checkpoint age target 3290529037 VS Checkpoint age 548376043
---------------
4 # Checkpoint age target 3290529037 VS Checkpoint age 548439480
---------------
5 # Checkpoint age target 3290529037 VS Checkpoint age 548496621
---------------
6 # Checkpoint age target 3290529037 VS Checkpoint age 548545047
---------------
7 # Checkpoint age target 3290529037 VS Checkpoint age 548595849
---------------
8 # Checkpoint age target 3290529037 VS Checkpoint age 548662636
---------------
9 # Checkpoint age target 3290529037 VS Checkpoint age 548710484
---------------
10 # Checkpoint age target 3290529037 VS Checkpoint age 548801833
---------------
11 # Checkpoint age target 3290529037 VS Checkpoint age 548863685
---------------
12 # Checkpoint age target 3290529037 VS Checkpoint age 548904796
---------------
13 # Checkpoint age target 3290529037 VS Checkpoint age 548968549
---------------
14 # Checkpoint age target 3290529037 VS Checkpoint age 549088662
---------------
15 # Checkpoint age target 3290529037 VS Checkpoint age 549132294
---------------
16 # Checkpoint age target 3290529037 VS Checkpoint age 549187664
---------------
17 # Checkpoint age target 3290529037 VS Checkpoint age 549253059
---------------
18 # Checkpoint age target 3290529037 VS Checkpoint age 549330765
---------------
19 # Checkpoint age target 3290529037 VS Checkpoint age 549395946
---------------
20 # Checkpoint age target 3290529037 VS Checkpoint age 549441201
---------------
21 # Checkpoint age target 3290529037 VS Checkpoint age 549492938
---------------
22 # Checkpoint age target 3290529037 VS Checkpoint age 549534003
---------------
23 # Checkpoint age target 3290529037 VS Checkpoint age 549612569
---------------
24 # Checkpoint age target 3290529037 VS Checkpoint age 549665522
---------------
25 # Checkpoint age target 3290529037 VS Checkpoint age 549717796
---------------
26 # Checkpoint age target 3290529037 VS Checkpoint age 549770229
---------------
27 # Checkpoint age target 3290529037 VS Checkpoint age 549820383
---------------
28 # Checkpoint age target 3290529037 VS Checkpoint age 549889603
---------------
29 # Checkpoint age target 3290529037 VS Checkpoint age 549931743
---------------
30 # Checkpoint age target 3290529037 VS Checkpoint age 549975421
---------------
31 # Checkpoint age target 3290529037 VS Checkpoint age 550028462
---------------
32 # Checkpoint age target 3290529037 VS Checkpoint age 550152857
---------------
33 # Checkpoint age target 3290529037 VS Checkpoint age 550217708
---------------
34 # Checkpoint age target 3290529037 VS Checkpoint age 550263237
---------------
35 # Checkpoint age target 3290529037 VS Checkpoint age 550326343
---------------
36 # Checkpoint age target 3290529037 VS Checkpoint age 550385828
---------------
37 # Checkpoint age target 3290529037 VS Checkpoint age 550438559
---------------
38 # Checkpoint age target 3290529037 VS Checkpoint age 550500763
---------------
39 # Checkpoint age target 3290529037 VS Checkpoint age 550596079
---------------
40 # Checkpoint age target 3290529037 VS Checkpoint age 550644519
---------------
41 # Checkpoint age target 3290529037 VS Checkpoint age 550709143
---------------
42 # Checkpoint age target 3290529037 VS Checkpoint age 550788273
---------------
43 # Checkpoint age target 3290529037 VS Checkpoint age 550847459
---------------
44 # Checkpoint age target 3290529037 VS Checkpoint age 550902149
---------------
45 # Checkpoint age target 3290529037 VS Checkpoint age 550960941
---------------
46 # Checkpoint age target 3290529037 VS Checkpoint age 551015013
---------------
47 # Checkpoint age target 3290529037 VS Checkpoint age 551085182
---------------
48 # Checkpoint age target 3290529037 VS Checkpoint age 551147923
---------------
49 # Checkpoint age target 3290529037 VS Checkpoint age 551200582
---------------
50 # Checkpoint age target 3290529037 VS Checkpoint age 551317590
---------------
51 # Checkpoint age target 3290529037 VS Checkpoint age 551370673
---------------
52 # Checkpoint age target 3290529037 VS Checkpoint age 551422936
---------------
53 # Checkpoint age target 3290529037 VS Checkpoint age 551475254
---------------
54 # Checkpoint age target 3290529037 VS Checkpoint age 551524226
---------------
55 # Checkpoint age target 3290529037 VS Checkpoint age 551575265
---------------
56 # Checkpoint age target 3290529037 VS Checkpoint age 551650437
---------------
57 # Checkpoint age target 3290529037 VS Checkpoint age 551674283
---------------
58 # Checkpoint age target 3290529037 VS Checkpoint age 551733831
---------------
59 # Checkpoint age target 3290529037 VS Checkpoint age 551820044
---------------
60 # Checkpoint age target 3290529037 VS Checkpoint age 551881626
---------------
61 # Checkpoint age target 3290529037 VS Checkpoint age 552026904
--
Best regards, Pavel
Vadim Tkachenko
Ok, and did you have slow queries during this time ?
--
林晓斌
Best regards, Pavel
Pavel Shevaev
> But I think the contrary conclusion may be more useful :
>
> Any time the slow queries appear, does the
> Innodb_buffer_pool_pages_free value decrease?
And if that the case what can I do about it?
--
Best regards, Pavel
Pavel Shevaev
Yes, I definitely had slow queries at that time. However I'll double
check it once I have a busy server again. Still are there any
anomalies in the log I provided?
--
Best regards, Pavel
Vadim Tkachenko
I do not see anomalies in log.
It seems it something different and it would require detailed analysis
to understand what's going on.
--
林晓斌
Best regards, Pavel
Pavel Shevaev
> "show global status like '%pages%';" and
> "show variables like 'innodb_max_dirty_pages_pct'; "
Sure:
mysql> show global status like '%pages%';
+----------------------------------+---------+
| Variable_name | Value |
+----------------------------------+---------+
| Innodb_buffer_pool_pages_data | 149841 |
| Innodb_buffer_pool_pages_dirty | 41017 |
| Innodb_buffer_pool_pages_flushed | 24242 |
| Innodb_buffer_pool_pages_free | 897516 |
| Innodb_buffer_pool_pages_misc | 1219 |
| Innodb_buffer_pool_pages_total | 1048576 |
| Innodb_dblwr_pages_written | 24242 |
| Innodb_pages_created | 2552 |
| Innodb_pages_read | 147289 |
| Innodb_pages_written | 24242 |
| Tc_log_max_pages_used | 0 |
+----------------------------------+---------+
mysql> show variables like 'innodb_max_dirty_pages_pct';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_max_dirty_pages_pct | 75 |
+----------------------------+-------+
--
Best regards, Pavel
林晓斌
Best regards, Pavel
Pavel Shevaev
> recently? If later, wait and paste again after the value decreases to
> zero.
Yes, due to data corruption it was restarted :( Ok, I'll wait then...
--
Best regards, Pavel
Pavel Shevaev
> Pavel,
>
> I do not see anomalies in log.
>
> It seems it something different and it would require detailed analysis
> to understand what's going on.
>
BTW, there's a small snapshot of the TRANSACTIONS section from INNODB
STATUS during busy time. I'm just wondering is it ok that it reports
that "mysql tables in use 1, locked 1" ? In normal conditions the
table shouldn't be locked, right?
---TRANSACTION 1D56CEE5, ACTIVE (PREPARED) 4 sec, process no 2824, OS
thread id 140203869103872 preparing
mysql tables in use 1, locked 1
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1
MySQL thread id 4698065, query id 40187418 192.168.2.1 od_castw freeing items
UPDATE player SET energy=3 WHERE id=527124
TABLE LOCK table `od_castw`.`player` trx id 1D56CEE5 lock mode IX
RECORD LOCKS space id 15 page no 12900 n bits 128 index `PRIMARY` of
table `od_castw`.`player` trx id 1D56CEE5 lock_mode X locks rec but
not gap
---TRANSACTION 1D56CEE4, ACTIVE (PREPARED) 4 sec, process no 2824, OS
thread id 140203878430464 preparing
mysql tables in use 1, locked 1
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1
MySQL thread id 4698064, query id 40187417 192.168.2.1 od_castw freeing items
UPDATE player SET money=190,rating=185,wood=203 WHERE id=183684
TABLE LOCK table `od_castw`.`player` trx id 1D56CEE4 lock mode IX
RECORD LOCKS space id 15 page no 4687 n bits 112 index `PRIMARY` of
table `od_castw`.`player` trx id 1D56CEE4 lock_mode X locks rec but
not gap
---TRANSACTION 1D56CEDF, ACTIVE (PREPARED) 4 sec, process no 2824, OS
thread id 140203882350336 preparing
mysql tables in use 1, locked 1
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1
MySQL thread id 4698062, query id 40187408 192.168.2.1 od_castw freeing items
UPDATE player SET rating=564 WHERE id=436789
TABLE LOCK table `od_castw`.`player` trx id 1D56CEDF lock mode IX
RECORD LOCKS space id 15 page no 10207 n bits 120 index `PRIMARY` of
table `od_castw`.`player` trx id 1D56CEDF lock_mode X locks rec but
not gap
--
Best regards, Pavel
Pavel Shevaev
> that "mysql tables in use 1, locked 1" ? In normal conditions the
> table shouldn't be locked, right?
Please ignore this question, looks like it's just a row level lock...
--
Best regards, Pavel
joh...@topcmm.com
Hi, Pavel. How's this problem going later then? Did you find out the cause of this?