Lots of effort trying to delete from 'down' host
Nathan Schmidt
nschmidt at gmail.com
Fri Mar 9 20:29:56 UTC 2007
This is probably more of a cautionary tale than a bug report but this
seems like a good way to capture this info.
We've been seeing vastly higher database utilization than we expected
- hundreds to thousands of inserts and deletes a second instead of
the 'several' we'd expected.
I traced this to an incomplete decommissioning of one of our hosts.
I'd used this machine for initial bring-up of our MogileFS system but
we've since moved it off to be a test machine.
mysql> select * from device where hostid=1;
+-------+--------+--------+--------+----------+---------+------------+
| devid | hostid | status | weight | mb_total | mb_used | mb_asof |
+-------+--------+--------+--------+----------+---------+------------+
| 1 | 1 | alive | 100 | 466170 | 154043 | 1172309562 |
+-------+--------+--------+--------+----------+---------+------------+
mysql> select * from host where hostid=1;
+--------+--------+-----------+---------------+----------
+--------------+-------+---------+
| hostid | status | http_port | http_get_port | hostname |
hostip | altip | altmask |
+--------+--------+-----------+---------------+----------
+--------------+-------+---------+
| 1 | down | 7500 | NULL | xxx | ---- |
NULL | NULL |
+--------+--------+-----------+---------------+----------
+--------------+-------+---------+
Whoops - just marking the host "down" isn't enough. Once I marked the
device "dead" our DB went from 2300 qps to 200 qps, which is much
more in line with our expectations given our application.
The strace and binlog dump below show the symptoms -- we did a couple
million deletes last week and it looks like the tracker was
repeatedly trying to propagate those deletes to the down host.
Regards,
-Nathan / PBwiki
------
Strace of mogilefsd [delete]:
18:12:03.896030 time(NULL) = 1173463923
18:12:03.896096 select(16, [12], NULL, NULL, {0, 0}) = 0 (Timeout)
18:12:03.896341 poll([{fd=4, events=POLLIN|POLLPRI}], 1, 0) = 0
18:12:03.896532 setsockopt(4, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.896581 write(4, "_\0\0\0\3INSERT IGNORE INTO file_to_"...,
99) = 99
18:12:03.896631 setsockopt(4, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.896736 read(4, "\7\0\0\1\0\1\0\2\0\0\0", 16384) = 11
18:12:03.897130 poll([{fd=4, events=POLLIN|POLLPRI}], 1, 0) = 0
18:12:03.897183 setsockopt(4, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.897225 write(4, ".\0\0\0\3DELETE FROM file_to_delete "...,
50) = 50
18:12:03.897367 setsockopt(4, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.897401 read(4, "\7\0\0\1\0\1\0\2\0\0\0", 16384) = 11
18:12:03.897665 time(NULL) = 1173463923
18:12:03.897841 select(16, [12], NULL, NULL, {0, 0}) = 0 (Timeout)
18:12:03.898020 poll([{fd=4, events=POLLIN|POLLPRI}], 1, 0) = 0
18:12:03.898060 setsockopt(4, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.898094 write(4, "_\0\0\0\3INSERT IGNORE INTO file_to_"...,
99) = 99
18:12:03.898143 setsockopt(4, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.898177 read(4, "\7\0\0\1\0\1\0\2\0\0\0", 16384) = 11
18:12:03.898532 poll([{fd=4, events=POLLIN|POLLPRI}], 1, 0) = 0
18:12:03.898603 setsockopt(4, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.898649 write(4, ".\0\0\0\3DELETE FROM file_to_delete "...,
50) = 50
18:12:03.898741 setsockopt(4, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.898775 read(4, "\7\0\0\1\0\1\0\2\0\0\0", 16384) = 11
18:12:03.899015 time(NULL) = 1173463923
18:12:03.899067 select(16, [12], NULL, NULL, {0, 0}) = 0 (Timeout)
18:12:03.899254 poll([{fd=4, events=POLLIN|POLLPRI}], 1, 0) = 0
18:12:03.899306 setsockopt(4, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.899366 write(4, "_\0\0\0\3INSERT IGNORE INTO file_to_"...,
99) = 99
18:12:03.899414 setsockopt(4, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.899459 read(4, "\7\0\0\1\0\1\0\2\0\0\0", 16384) = 11
18:12:03.899776 poll([{fd=4, events=POLLIN|POLLPRI}], 1, 0) = 0
18:12:03.899843 setsockopt(4, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.899889 write(4, ".\0\0\0\3DELETE FROM file_to_delete "...,
50) = 50
18:12:03.899962 setsockopt(4, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.900012 read(4, "\7\0\0\1\0\1\0\2\0\0\0", 16384) = 11
18:12:03.900264 time(NULL) = 1173463923
18:12:03.900315 select(16, [12], NULL, NULL, {0, 0}) = 0 (Timeout)
18:12:03.900463 poll([{fd=4, events=POLLIN|POLLPRI}], 1, 0) = 0
18:12:03.900512 setsockopt(4, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.900565 write(4, "_\0\0\0\3INSERT IGNORE INTO file_to_"...,
99) = 99
18:12:03.900613 setsockopt(4, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.900647 read(4, "\7\0\0\1\0\1\0\2\0\0\0", 16384) = 11
18:12:03.900903 poll([{fd=4, events=POLLIN|POLLPRI}], 1, 0) = 0
18:12:03.900979 setsockopt(4, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
18:12:03.901027 write(4, ".\0\0\0\3DELETE FROM file_to_delete "...,
50) = 50
18:12:03.901098 setsockopt(4, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0
\0\0\0", 8) = 0
Dump from binlog (all ops have the same timestamp):
SET TIMESTAMP=1173461541;
INSERT IGNORE INTO file_to_delete_later (fid, delafter) VALUES
('6602935',UNIX_TIMESTAMP()+600);
# at 123377
#070309 17:32:21 server id 1 end_log_pos 123538 Query
thread_id=68327 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
INSERT IGNORE INTO file_to_delete_later (fid, delafter) VALUES
('467313',UNIX_TIMESTAMP()+600);
# at 123538
#070309 17:32:21 server id 1 end_log_pos 123651 Query
thread_id=68304 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
DELETE FROM file_to_delete WHERE fid='6602935';
# at 123651
#070309 17:32:21 server id 1 end_log_pos 123763 Query
thread_id=68327 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
DELETE FROM file_to_delete WHERE fid='467313';
# at 123763
#070309 17:32:21 server id 1 end_log_pos 123925 Query
thread_id=68304 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
INSERT IGNORE INTO file_to_delete_later (fid, delafter) VALUES
('7921533',UNIX_TIMESTAMP()+600);
# at 123925
#070309 17:32:21 server id 1 end_log_pos 124086 Query
thread_id=68327 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
INSERT IGNORE INTO file_to_delete_later (fid, delafter) VALUES
('758517',UNIX_TIMESTAMP()+600);
# at 124086
#070309 17:32:21 server id 1 end_log_pos 124199 Query
thread_id=68304 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
DELETE FROM file_to_delete WHERE fid='7921533';
# at 124199
#070309 17:32:21 server id 1 end_log_pos 124311 Query
thread_id=68327 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
DELETE FROM file_to_delete WHERE fid='758517';
# at 124311
#070309 17:32:21 server id 1 end_log_pos 124473 Query
thread_id=68304 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
INSERT IGNORE INTO file_to_delete_later (fid, delafter) VALUES
('7922858',UNIX_TIMESTAMP()+600);
# at 124473
#070309 17:32:21 server id 1 end_log_pos 124635 Query
thread_id=68327 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
INSERT IGNORE INTO file_to_delete_later (fid, delafter) VALUES
('7907471',UNIX_TIMESTAMP()+600);
# at 124635
#070309 17:32:21 server id 1 end_log_pos 124748 Query
thread_id=68304 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
DELETE FROM file_to_delete WHERE fid='7922858';
# at 124748
#070309 17:32:21 server id 1 end_log_pos 124861 Query
thread_id=68327 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
DELETE FROM file_to_delete WHERE fid='7907471';
# at 124861
#070309 17:32:21 server id 1 end_log_pos 125023 Query
thread_id=68304 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
INSERT IGNORE INTO file_to_delete_later (fid, delafter) VALUES
('7918895',UNIX_TIMESTAMP()+600);
# at 125023
#070309 17:32:21 server id 1 end_log_pos 125184 Query
thread_id=68327 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
INSERT IGNORE INTO file_to_delete_later (fid, delafter) VALUES
('351057',UNIX_TIMESTAMP()+600);
# at 125184
#070309 17:32:21 server id 1 end_log_pos 125297 Query
thread_id=68304 exec_time=0 error_code=0
SET TIMESTAMP=1173461541;
DELETE FROM file_to_delete WHERE fid='7918895';
# at 125297
More information about the mogilefs
mailing list