Mysql – Queries hung for no specific reason

I'm having a strange issues for the past few days. I run data updates at night that shouldn't take more than a few hours.

Several weeks ago a single script took two days to complete. I ran it again when the server wasn't processing anything and it took minutes.

I figured this is some kind of race condition, or something triggered when the server load is high.

It is indeed reproduced every night, but not on the same step. I mean I update a lot of databases that are similarly processed. It won't fail on the same database every night, but it will fail on the same specific query.

Here's the specific query:

create temporary table trip_types (
    id int unsigned not null auto_increment primary key,
    stops_taken varchar(32) not null default '',
    index trip_type_idx (stops_taken)
)
select (
    select md5(group_concat(st.stop_iid))
    from stop_times st
    where st.trip_iid = t.id
    group by st.trip_iid
    order by st.stop_sequence
) as stops_taken
from trips t
group by stops_taken;

update trips t
set trip_type = (
    select id
    from trip_types
    where stops_taken = (
        select md5(group_concat(stop_iid))
        from stop_times
        where trip_iid = t.id
        group by trip_iid
        order by stop_sequence asc
    )
    group by stops_taken
);

Basically a trip is a collection of stops (+ time of departure, hence stop_times), ordered by stop.stop_sequence. I want to compare identical trips regardless of the time of departure, hence I'm comparing the ordered list of stops taken.

My goal is to have an INT in the trips table that would indicate the trip type (list of trips taken), so that I can differentiate trips just using the INT column:

• take one trip
• compute list of stops taken
• save as md5 in a temp table
• once all trips are computed, put back the ID of the temp table in the trips table

So my script does this in two steps: compute md5 and store in temp table, then fill back into trips.

I had an optimized query for computing the md5, however my SQL client crashed and destroyed my work 🙂 I'll have to do it again. I'm just saying, because I think there is room for improvement in these queries.

Now I have read some documentation here and there, including this blog post that describes an issue that is very similar to mine.

I have plotted similar graphs from my server, here's one occurrence:

As you can see there is a very intense use of Pool requests, as well as MySQL handler read next. As the doc says, either my query or my table design is poor:

The number of requests to read the next row in the data file. This value is high if you are doing a lot of table scans. Generally this suggests that your tables are not properly indexed or that your queries are not written to take advantage of the indexes you have.

Here's the trips table:

CREATE TABLE `trips` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `trip_id` varchar(100) NOT NULL,
  `trip_headsign` varchar(255) DEFAULT NULL,
  `trip_short_name` varchar(255) DEFAULT NULL,
  `route_id` varchar(100) NOT NULL,
  `route_iid` int(11) NOT NULL,
  `service_id` varchar(100) NOT NULL,
  `trip_type` int(11) NOT NULL,
  `direction_id` tinyint(1) DEFAULT NULL,
  `block_id` varchar(11) DEFAULT NULL,
  `shape_id` varchar(100) DEFAULT NULL,
  `shape_iid` int(11) DEFAULT NULL,
  `wheelchair_accessible` tinyint(1) DEFAULT NULL,
  `bikes_allowed` tinyint(1) DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `trip_id_UNIQUE` (`trip_id`),
  KEY `direction_id` (`direction_id`),
  KEY `block_id` (`block_id`),
  KEY `shape_id` (`shape_id`),
  KEY `route_iidx` (`route_iid`),
  KEY `trip_type_idx` (`trip_type`),
  KEY `trip_shape_idx` (`shape_iid`),
  CONSTRAINT `trip_route_id` FOREIGN KEY (`route_iid`) REFERENCES `routes` (`id`),
  CONSTRAINT `trip_shape` FOREIGN KEY (`shape_iid`) REFERENCES `shapes` (`id`) ON DELETE NO ACTION ON UPDATE NO ACTION
) ENGINE=InnoDB DEFAULT CHARSET=utf8

Here's the stop_times table:

CREATE TABLE `stop_times` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `arrival_time` time NOT NULL,
  `arrival_time_seconds` int(100) DEFAULT NULL,
  `idep` int(11) NOT NULL,
  `hour` tinyint(2) NOT NULL DEFAULT '-1',
  `departure_time` time NOT NULL,
  `departure_time_seconds` int(100) DEFAULT NULL,
  `stop_id` varchar(100) NOT NULL,
  `stop_iid` int(11) NOT NULL,
  `stop_sequence` int(11) NOT NULL,
  `stop_headsign` varchar(50) DEFAULT NULL,
  `pickup_type` varchar(2) DEFAULT NULL,
  `drop_off_type` varchar(2) DEFAULT NULL,
  `shape_dist_traveled` varchar(50) DEFAULT NULL,
  `trip_id` varchar(100) NOT NULL,
  `trip_iid` int(11) NOT NULL,
  `timepoint` tinyint(1) DEFAULT NULL,
  PRIMARY KEY (`id`,`hour`),
  KEY `stop_iidx` (`stop_iid`),
  KEY `trip_iidx` (`trip_iid`),
  KEY `idep_idx` (`idep`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
/*!50100 PARTITION BY RANGE (hour)
(PARTITION p0 VALUES LESS THAN (1) ENGINE = InnoDB,
 PARTITION p1 VALUES LESS THAN (2) ENGINE = InnoDB,
 ... truncated for clarity... you get the idea ...
 PARTITION p29 VALUES LESS THAN (30) ENGINE = InnoDB,
 PARTITION p30 VALUES LESS THAN (1000) ENGINE = InnoDB) */

I have worked on these, I think they're good. If you see something stupid, please point it out!

As per the query, here's the temp table select:

*************************** 1. row ***************************
           id: 1
  select_type: PRIMARY
        table: t
   partitions: NULL
         type: index
possible_keys: NULL
          key: direction_id
      key_len: 2
          ref: NULL
         rows: 30065
     filtered: 100.00
        Extra: Using index; Using temporary; Using filesort
*************************** 2. row ***************************
           id: 2
  select_type: DEPENDENT SUBQUERY
        table: st
   partitions: p0,p1,p2,p3,p4,p5,p6,p7,p8,p9,p10,p11,p12,p13,p14,p15,p16,p17,p18,p19,p20,p21,p22,p23,p24,p25,p26,p27,p28,p29,p30
         type: ref
possible_keys: trip_iidx
          key: trip_iidx
      key_len: 4
          ref: t.id
         rows: 22
     filtered: 100.00
        Extra: Using index condition; Using temporary; Using filesort

Here's the update:

*************************** 1. row ***************************
           id: 1
  select_type: UPDATE
        table: t
   partitions: NULL
         type: index
possible_keys: NULL
          key: PRIMARY
      key_len: 4
          ref: NULL
         rows: 30065
     filtered: 100.00
        Extra: NULL
*************************** 2. row ***************************
           id: 2
  select_type: DEPENDENT SUBQUERY
        table: trip_types
   partitions: NULL
         type: ref
possible_keys: trip_type_idx
          key: trip_type_idx
      key_len: 34
          ref: func
         rows: 1
     filtered: 100.00
        Extra: Using where; Using index
*************************** 3. row ***************************
           id: 3
  select_type: DEPENDENT SUBQUERY
        table: stop_times
   partitions: p0,p1,p2,p3,p4,p5,p6,p7,p8,p9,p10,p11,p12,p13,p14,p15,p16,p17,p18,p19,p20,p21,p22,p23,p24,p25,p26,p27,p28,p29,p30
         type: ref
possible_keys: trip_iidx
          key: trip_iidx
      key_len: 4
          ref: dbname.t.id
         rows: 22
     filtered: 100.00
        Extra: Using index condition; Using temporary; Using filesort
3 rows in set, 1 warning (0.00 sec)

What's weird is that currently the server is failing hard and it will be stuck for hours. However if I kill the query and stop the script; then run the query again it will be gone much faster:

1. Identify the query

   *************************** 62. row ***************************
          Id: 1460
        User: johndoe
        Host: foobar:46842
          db: xxxyyyzzz
     Command: Query
        Time: 3365
       State: Sending data
        Info: create temporary table trip_types (
         id int unsigned not null auto_increment primary key,
         stops_tak
   

2. Kill it

   mysql> kill 1460;
   Query OK, 0 rows affected (0.00 sec)
   

3. Do it again, by hand:

   This block is invalid, as it is related to my mistake in the query. Please see edits of this question to fully understand.

   I didn't have any new occurrence so I can't run it again to see how fast it is. What's sure, is it's faster.

   Also, on the next occurrence I'll try the explain on the active query, to see what exactly happens. Stay tuned! 🙂

   mysql> truncate stop_connections;</strike>
   Query OK, 0 rows affected (0.95 sec)
   
   mysql> insert into stop_connections (from_stop_iid, to_stop_iid, distance)
       -> select s.id as sid, d.id as did, pow(s.stop_lat - d.stop_lat, 2) + pow(s.stop_lon - d.stop_lon, 2) as distance
       -> from stops s, stops d
       -> where d.id <> s.id
       -> having distance < 0.00000683497
       -> on duplicate key update from_stop_iid = from_stop_iid;
   Query OK, 15172 rows affected (50.04 sec)
   Records: 15172  Duplicates: 0  Warnings: 0
   

Fifty seconds. It was stuck for about an hour, but ran manually it was done in seconds.

From my various reading online, here are the customisations I made to my.cnf:

# http://stackoverflow.com/questions/24860111/warning-a-long-semaphore-wait
innodb_adaptive_hash_index = 0

# https://bugs.mysql.com/bug.php?id=59047 comment [1 Mar 2011 23:47] James Day
# https://dev.mysql.com/doc/refman/5.7/en/query-cache.html
query_cache_size = 0

# http://stackoverflow.com/a/414934/334493
# http://dev.mysql.com/doc/refman/5.1/en/innodb-parameters.html#sysvar_innodb_flush_log_at_trx_commit
innodb_flush_log_at_trx_commit = 2

Each parameter is documented with SO question/answer, bug or links to the MySQL doc.

As you can see from said linked question, I've also had a lot of crashes. I've monitored the result of show status like 'Uptime':

The server crashes a lot. At least once a day. It seems it gets stuck on semaphores, and gives up waiting and crashes itself. Here are extracts from /var/log/mysql/error.log ()

--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 799.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 807.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 827.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 830.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 847.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 861.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 867.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 887.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 892.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 907.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 923.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 927.00 seconds the semaphore:
--Thread 140522828371712 has waited at buf0flu.cc line 1198 for 947.00 seconds the semaphore:

Or:

2015-10-10T01:23:43.993606Z 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2015-10-11T01:53:16.961205Z 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2015-10-11T13:48:43.767908Z 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2015-10-12T01:42:34.522508Z 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2015-10-12T04:37:18.720553Z 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.

In the hours/minutes before self destruction, the server dumps SHOW ENGINE INNODB STATUS, which I failed to interpret. I just see that it's waiting for semaphores created at various places in the code. I've had a look at the source code but I don't have the knowledge to understand what's going on.
Here are the code lines that generated most of the semaphore waits (1st number is number of occurrences):

9656 buf0flu.cc:1062
1381 trx0undo.cc:1778
1115 buf0flu.cc:1198
 832 dict0boot.ic:36
 792 srv0srv.cc:2000
 544 dict0dict.cc:1089
 517 row0ins.cc:1791

It seems that buf0flu.cc:1062 would be the #1 hang generator. Well, I don't know what to do with that 🙂

So here's my issue. I've been wondering and thinking what I did wrong and what I could do to fix this, but now I'm stuck.

Any ideas?

---

SW: Debian 8, Linux 3.16.0, MySQL 5.7.8-rc-log
HW: HP MicroServer ProLiant G8, Intel Celeron 1610T, 2GB RAM, System on 850 EVO SSD and Database on Seagate 2TB hard drive.

MySQL tmpdir is on a 384MB ramdisk, which once was filled with temptables (and no space left on device). I considered using the SSD as the tmpdir. I'm not sure it is relevant here.

---

Clarifications about the table schema / application flow.

Three tables are chained: trips, stop_times and stops.

• a stop is basically an ID and lat/lon
• a stop_time is a stop + a timestamp, say 11am
• a trip is a collection of stop_times, chained by stop_sequence

So if I have 4 stops: A, B, C and D, I could have many stop_times:

• stop_time #1: A at 11am
• stop_time #2: A at 11:05am
• stop_time #3: A at 11:10am
• stop_time #4: B at 11:06am
• stop_time #5: C at 11:07am
• stop_time #6: D at 11:08am

I could have several trips like this:

• trip #1: uses stop_times #1, #4, #5 and #6 (stops ABCD starting at 11am)
• trip #2: uses stop_times #1 and #6 (stops AD starting at 11am)
• trip #3: uses stop_times #2, #7, #8… (stops ABCD starting at 11:05am)
• etc

I want to identify identical trips in terms of stops taken. Here, trips #1 and #3 share the same stop sequence: ABCD. Trip #2 uses the same path from A to D, however it's not the same trip type because it doesn't make the stops at B and C.

---

I have done some benchmarking to improve the query: create an external (non temp) table to store a mapping between trip IDs and trip types (group_concat of used stops)

1. Store trip ID + trip type as is, in a text field (sequence of stops: 1,543,343,394,10,...)
2. Store trip ID + trip type as md5 of the stops sequence, in a char(32)

When used by the application, the trip typed is used in a group by statement. Joining the external table and grouping made the performance drop by a factor of 5x to 10x.

I have successfully optimized the trip type generation though, by computing the stop sequence only once:

1. Add a column stops_taken to trips as a text or a char(32) (depending on the risk of md5 collision)
2. Fill this column
3. Fill a temp table with these values to generate IDs (auto increment)
4. Put back the trip type ID in the trips table.

Here's the new script:

update trips t
set stops_taken = (
  select md5(group_concat(stop_iid))
  from stop_times
  where trip_iid = t.id
  group by trip_iid
  order by stop_sequence asc
);
create temporary table trip_types (
    id int unsigned not null auto_increment primary key,
    stops_taken char(32) not null,
    key st (stops_taken)
);
insert into trip_types(stops_taken) select distinct stops_taken from trips;
update trips t join trip_types tt on tt.stops_taken = t.stops_taken
set t.trip_type = tt.id;

On one DB, this reduces the execution time from ~32-40s to ~23s. That's a nice ~35% drop.

---

I could reproduce the issue with this new script. Handler read next counter went up like crazy and it's been stuck on the query for more than 10 minutes now.

I saw that while this is not normal, this doesn't necessarily crash the server. What does is the rise of the semaphore wait time counter: see the rise causing a crash (the 11pm restart of mysql was mine):

For now this counter is 0 so I'm not risking any mysql crash. However it is stuck, and thanks to @jkavalik suggestion, I could see what is the query causing it:

update trips t
set stops_taken = (
  select md5(group_concat(stop_iid))
  from stop_times
  where trip_iid = t.id
  group by trip_iid
  order by stop_sequence asc
);

So that's indeed the md5/stop sequence generation.

What puzzles me is if I'm doing the same query without updating the trips table, it goes nicely:

mysql> select t.id, tt.*
    -> from
    -> trips t
    -> left join (
    ->   select trip_iid, md5(group_concat(stop_iid))
    ->   from stop_times
    ->   group by trip_iid
    ->   order by stop_sequence asc
    -> ) tt on tt.trip_iid = t.id;
+-------+----------+----------------------------------+
| id    | trip_iid | md5(group_concat(stop_iid))      |
+-------+----------+----------------------------------+
|     1 |        1 | 06e9d5dbd52703144d4244c6720cdeb2 |
|     2 |        2 | 6e6b7899a4668bf0a0c88e07d9adc337 |
|     3 |        3 | 6e6b7899a4668bf0a0c88e07d9adc337 |
...
| 11726 |    11726 | adebbf5bb888e38fb55a97b5a9c83763 |
| 11728 |    11728 | 1b76be03f1202110f62c74e6ddac2119 |
+-------+----------+----------------------------------+
11729 rows in set (2.79 sec)

Finished in less than 3 seconds. The other query is still stuck, now it's been stuck for 15 minutes.

ALTER TABLE trips DROP KEY trip_type_idx;

CREATE TEMPORARY TABLE trans_trip_types (
    trip_id         unsigned    not null primary key,
    md5_stops_taken varchar(32) not null,
    INDEX           idx_md5 (md5_stops_taken)
)
  SELECT st.trip_iid AS trip_id,
         md5(Group_Concat(DISTINCT st.stop_iid ORDER BY st.stop_sequence)) AS md5_stops_taken
    FROM stop_times AS st
    JOIN trips t
      ON st.trip_iid = t.id
GROUP BY st.trip_iid;

create temporary table trip_types (
    id          int unsigned autonumber not null primary key, -- back to autonumber
    stops_taken varchar(32)             not null default '',
    INDEX       trip_type_idx (stops_taken)
)
SELECT DISTINCT md5_stops_taken AS stops_taken
FROM trans_trip_types ORDER BY md5_stops_taken;

UPDATE trips AS t
    SET t.trip_type = 
      (SELECT tt.id
         FROM trans_trip_types AS ttt
         JOIN trip_types AS tt
           ON tt.stops_taken = ttt.stops_taken 
        WHERE ttt.trip_iid = t.trip_iid
        LIMIT 1
      );

DROP trans_trip_types;

ALTER TABLE trips ADD KEY trip_type_idx (trip_type);

EXPLAIN SELECT l.id, l.level_name, l.date_published, l.rating
FROM levels AS l
INNER JOIN users_favorites AS uf 
ON uf.level_id = l.id
WHERE l.user_id = 2;