Website going down, cannot understand webserver process logs?

Question

could anyone help to explain the following log:

MariaDB [(none)]> show full processlist;
+--------+----------------+-----------------+---------------------+---------+-----
|      3 | user-rw        | localhost       | bets-stage          | Sleep   |   51 |                      | NULL                                                                                                  |    0.000 |
|     11 | user-rw        | localhost       | bets-stage          | Sleep   |   39 |                      | NULL                                                                                      |    0.000 |
|     13 | db1029865-news | localhost       | db1029865-sportnews | Query   |   30 | Writing to net       | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc                                                                                                                                                                 |    0.000 |
|     17 | db1029865-news | localhost       | db1029865-sportnews | Query   |   20 | Writing to net       | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc                                                                                                                                                                                                                                                                                                                         |    0.000 |
|     34 | db1029865-news | localhost       | db1029865-sportnews | Query   |    3 | Sorting result       | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc   |    0.000 |
|     37 | db1029865-news | localhost       | db1029865-sportnews | Sleep   |   31 |                      | NULL |    0.000 |
|     39 | user-rw        | localhost       | bets-stage          | Sleep   |   77 |                      | NULL                                                                            |    0.000 |
|     40 | db1029865-news | localhost       | db1029865-sportnews | Query   |   16 | Writing to net       | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc                                                                                     |    0.000 |
|     41 | user-rw        | localhost       | bets-stage          | Sleep   |   43 |                      | NULL                                                                                     |    0.000 |
|     49 | db1029865-news | localhost       | db1029865-sportnews | Query   |   24 | Writing to net       | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc                                                                                     |    0.000 |
|     52 | db1029865-news | localhost       | db1029865-sportnews | Sleep   |   36 |                      | NULL                                                                                     |    0.000 |
|     53 | db1029865-news | localhost       | db1029865-sportnews | Query   |   26 | Writing to net       | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc                                                                                     |    0.000 |
|     54 | db1029865-news | localhost       | db1029865-sportnews | Query   |    1 | Copying to tmp table | SELECT `post`.*, `post`.`team1_seourl` AS `team1seourl`, `post`.`team1_seourl` AS `teamseourl`, `post`.`team2_seourl` AS `team2seourl`, IF(`temp_tn1uid`.`value` > 0, `post`.`team1_uid`, NULL) AS `tn1uid`, IF(`temp_tn2uid`.`value` > 0, `post`.`team2_uid`, NULL) AS `tn2uid` FROM (SELECT `post`.*, `post_j`.`title`, `post_j`.`teaser` FROM (SELECT `post`.* FROM `sportnews_cache_post_team` AS `post` FORCE INDEX(`sort_index`) JOIN (SELECT `cache_uid` FROM `sportnews_cache_post_team` AS `post` WHERE (`post`.`team1_uid` = 4894 OR `post`.`team2_uid` = 4894) GROUP BY `post`.`uid` ORDER BY `post`.`cache_uid` LIMIT 40 OFFSET 0) AS `post_j` ON `post`.`cache_uid` = `post_j`.`cache_uid`) AS `post` JOIN `sportnews_post` AS `post_j` ON `post_j`.`uid` = `post`.`uid`) AS `post` LEFT JOIN (SELECT `uid`, COUNT(*) AS `value` FROM `sportnews_cache_post_team` AS `post` FORCE INDEX(`sort_index`) WHERE `post`.`team1_uid` = 4894 GROUP BY `post`.`uid`) AS `temp_tn1uid` ON `temp_tn1uid`.`uid` = `post`.`uid` LEFT JOIN (SELECT `uid`, COUNT(*) AS `value` FROM `sportnews_cache_post_team` AS `post` FORCE INDEX(`sort_index`) WHERE `post`.`team2_uid` = 4894 GROUP BY `post`.`uid`) AS `temp_tn2uid` ON `temp_tn2uid`.`uid` = `post`.`uid` |    0.000 |
|     57 | db1029865-news | localhost       | db1029865-sportnews | Sleep   |   22 |                      | NULL                                                                                     |    0.000 |
|     75 | user-rw        | localhost       | bets-stage          | Sleep   |   32 |                      | NULL                                                                                     |    0.000 |
|     77 | db1029865-news | localhost       | db1029865-sportnews | Sleep   |    6 |                      | NULL                                                                                     |    0.000 |
|     78 | db1029865-news | localhost       | db1029865-sportnews | Sleep   |   15 |                      | NULL                                                                                     |    0.000 |
|     79 | db1029865-news | localhost       | db1029865-sportnews | Sleep   |    3 |                      | NULL                                                                                     |    0.000 |
|     88 | db1029865-news | localhost       | db1029865-sportnews | Query   |   18 | Writing to net       | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc                                                                                     |    0.000 |
|     99 | db1029865-news | localhost       | db1029865-sportnews | Sleep   |   39 |                      | NULL                                                                                     |    0.000 |
|    100 | db1029865-news | localhost       | db1029865-sportnews | Query   |    1 | Sorting result       | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc                                                                                                                                                                   |    0.000 |
|    110 | db1029865-news | localhost       | db1029865-sportnews | Query   |   32 | Writing to net       | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc                                                                                                                                                                   |    0.000 |
|    117 | db1029865-news | localhost       | db1029865-sportnews | Sleep   |    9 |                      | NULL                                                                                                                                                                   |    0.000 |
|    119 | user-rw        | localhost       | bets-stage          | Sleep   |   70 |                      | NULL                                                                                                                                                                   |    0.000 |
|    137 | user-rw        | localhost       | bets-stage          | Sleep   |   34 |                      | NULL                                                                                     |    0.000 |
|    138 | db1029865-news | localhost       | db1029865-sportnews | Query   |   28 | Sending data         | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc                                                                                     |    0.000 |
|    160 | user-rw        | localhost       | bets-stage          | Sleep   |   40 |                      | NULL                                                                                     |    0.000 |
|    162 | user-rw        | localhost       | bets-stage          | Sleep   |   27 |                      | NULL                                                                                     |    0.000 |
|    189 | user-rw        | localhost       | bets-stage          | Sleep   |   19 |                      | NULL       |    0.000 |
|    208 | user-rw        | localhost       | bets-stage          | Sleep   |   56 |                      | NULL       |    0.000 |
|    218 | db1029865-news | localhost       | db1029865-sportnews | Query   |   22 | Writing to net       | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc                                                                                                                                                                   |    0.000 |
|    219 | user-rw        | localhost       | bets-stage          | Sleep   |    3 |                      | NULL                                                                                                                                                                   |    0.000 |
|    274 | user-rw        | localhost       | bets-stage          | Sleep   |   20 |                      | NULL                                                                                                                                                                   |    0.000 |
|    301 | user-rw        | localhost       | bets-stage          | Sleep   |   30 |                      | NULL                                                                                     |    0.000 |
|    302 | user-rw        | localhost       | bets-stage          | Sleep   |    2 |                      | NULL                                                                                                                                                                   |    0.000 |
|    356 | user-rw        | localhost       | bets-stage          | Sleep   |   36 |                      | NULL                                                                                                                                                                   |    0.000 |
|    435 | user-rw        | localhost       | bets-stage          | Sleep   |   55 |                      | NULL       |    0.000 |
|    511 | user-rw        | localhost       | bets-stage          | Sleep   |   59 |                      | NULL                                                                                                                                                                   |    0.000 |
|   2007 | user-rw        | localhost       | bets-stage          | Sleep   |   61 |                      | NULL                                                                                                                                                                   |    0.000 |
| 606299 | db1029865-news | localhost:34857 | db1029865-sportnews | Sleep   |   60 |                      | NULL                                                                                                                                                                   |    0.000 |
| 606300 | db1029865-news | localhost:34860 | db1029865-sportnews | Sleep   |   60 |                      | NULL                                                                                                                                                                   |    0.000 |
| 606438 | db1029865-news | localhost:34940 | db1029865-sportnews | Sleep   |   91 |                      | NULL                                                                                     |    0.000 |
| 606439 | db1029865-news | localhost:34941 | db1029865-sportnews | Sleep   |    3 |                      | NULL                                                                                     |    0.000 |
| 610631 | user-rw        | localhost:35813 | sportnews-stage     | Sleep   |  177 |                      | NULL                                                                                                                                                                   |    0.000 |
| 611528 | db1029865-news | localhost:36298 | db1029865-sportnews | Query   |   10 | Writing to net       | SELECT /*!40001 SQL_NO_CACHE */ * FROM `sportnews_log`                                                                                                                                                                                               |    0.000 |
| 612224 | root           | localhost       | NULL                | Query   |    0 | NULL                 | show full processlist                                                                                                                                                  |    0.000 |
+--------+----------------+-----------------+---------------------+---------+------+----------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
47 rows in set (0.00 sec)
|     13 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   24 | Writing to net   | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     17 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   21 | Sending data     | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     34 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   10 | Sorting result   | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     37 | db1029865-news       | localhost       | db1029865-sportnews | Query   |    6 | Sorting result   | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     39 | user-rw              | localhost       | bets-stage          | Sleep   |   38 |                  | NULL                                                                                                                                                             |    0.000 |
|     40 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   21 | Sending data     | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     41 | user-rw              | localhost       | bets-stage          | Sleep   |  139 |                  | NULL                                                                                                                                                             |    0.000 |
|     49 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   25 | Sending data     | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     52 | db1029865-news       | localhost       | db1029865-sportnews | Query   |    8 | Sorting result   | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     53 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   20 | Writing to net   | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     54 | db1029865-news       | localhost       | db1029865-sportnews | Query   |    7 | Sorting result   | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     57 | db1029865-news       | localhost       | db1029865-sportnews | Sleep   |   48 |                  | NULL                                                                                                                                                             |    0.000 |
|     75 | user-rw              | localhost       | bets-stage          | Sleep   |   33 |                  | NULL                                                                                                                                                             |    0.000 |
|     77 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   28 | Sending data     | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     78 | db1029865-news       | localhost       | db1029865-sportnews | Sleep   |   29 |                  | NULL                                                                                                                                                             |    0.000 |
|     79 | db1029865-news       | localhost       | db1029865-sportnews | Sleep   |    6 |                  | NULL                                                                                                                                                             |    0.000 |
|     88 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   14 | Sorting result   | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|     99 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   10 | Sorting result   | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|    100 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   13 | Sorting result   | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|    110 | db1029865-news       | localhost       | db1029865-sportnews | Sleep   |    4 |                  | NULL                                                                                                                                                             |    0.000 |
|    117 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   34 | Sending data     | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|    119 | user-rw              | localhost       | bets-stage          | Sleep   |   10 |                  | NULL                                                                                                                                                             |    0.000 |
|    137 | user-rw              | localhost       | bets-stage          | Sleep   |   24 |                  | NULL                                                                                                                                                             |    0.000 |
|    138 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   31 | Sending data     | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc |    0.000 |
|    160 | user-rw              | localhost       | bets-stage          | Sleep   |  260 |                  | NULL                                                                                                                                                             |    0.000 |
|    162 | user-rw              | localhost       | bets-stage          | Sleep   |  136 |                  | NULL                                                                                                                                                             |    0.000 |
|    189 | user-rw              | localhost       | bets-stage          | Sleep   |   14 |                  | NULL                                                                                                                                                             |    0.000 |
|    208 | user-rw              | localhost       | bets-stage          | Sleep   |   10 |                  | NULL                                                                                                                                                             |    0.000 |
|    218 | db1029865-news       | localhost       | db1029865-sportnews | Query   |   24 | Sending data     | SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'

I can't see an error or failure in this log. It seems they are just `info` log entries on SELECT statements that have completed successfully. — Alex, Apr 24 '15 at 12:09
Can you give us more details? Which part goes down? When does it go down? Did this occur just once or multiple times? Is there any pattern visible? What about other daemon logs? — scai, Apr 24 '15 at 12:12
The whole website goes down from time to time, and it has occurred multiple time. Ill see if i can attach the apache logs — user2431436, Apr 24 '15 at 12:29

score 0 · Answer 1 · answered Apr 24 '15 at 12:41

As commented by few users, more information is required to know the exact problem.

From the processlist output you have provided it is seen that many of your queries are stuck in the state "writing to net" for 20-30 seconds range. This means that either your select queries are returning huge amount of data and taking long tome to write the packet to the network or your network is slow/throttled by some other process and making the mysql output slow.

If any page was using these queries they will not be geeting result for 20-30 seconds (equivalent of website down)

Thanks, yes I will get the apache logs and update it soon. thank you very much for your help. I appreciate it — user2431436, Apr 24 '15 at 12:47

score 0 · Answer 2 · edited Jun 20 '20 at 09:12

1. Hudge stress on DB

I personally would blame this:

SELECT `post`.*,
       `post`.`team1_seourl` AS `team1seourl`,
       `post`.`team1_seourl` AS `teamseourl`,
       `post`.`team2_seourl` AS `team2seourl`,
       IF(`temp_tn1uid`.`value` > 0, `post`.`team1_uid`, NULL) AS `tn1uid`,
       IF(`temp_tn2uid`.`value` > 0, `post`.`team2_uid`, NULL) AS `tn2uid`
FROM
  (SELECT `post`.*,
          `post_j`.`title`,
          `post_j`.`teaser`
   FROM
     (SELECT `post`.*
      FROM `sportnews_cache_post_team` AS `post`
      FORCE INDEX(`sort_index`)
      JOIN
        (SELECT `cache_uid`
         FROM `sportnews_cache_post_team` AS `post`
         WHERE (`post`.`team1_uid` = 4894
                OR `post`.`team2_uid` = 4894)
         GROUP BY `post`.`uid`
         ORDER BY `post`.`cache_uid` LIMIT 40
         OFFSET 0) AS `post_j` ON `post`.`cache_uid` = `post_j`.`cache_uid`) AS `post`
   JOIN `sportnews_post` AS `post_j` ON `post_j`.`uid` = `post`.`uid`) AS `post`
LEFT JOIN
  (SELECT `uid`,
          COUNT(*) AS `value`
   FROM `sportnews_cache_post_team` AS `post`
   FORCE INDEX(`sort_index`)
   WHERE `post`.`team1_uid` = 4894
   GROUP BY `post`.`uid`) AS `temp_tn1uid` ON `temp_tn1uid`.`uid` = `post`.`uid`
LEFT JOIN
  (SELECT `uid`,
          COUNT(*) AS `value`
   FROM `sportnews_cache_post_team` AS `post`
   FORCE INDEX(`sort_index`)
   WHERE `post`.`team2_uid` = 4894
   GROUP BY `post`.`uid`) AS `temp_tn2uid` ON `temp_tn2uid`.`uid` = `post`.`uid`

From your log. I haven't occured a DB engine that will join that much subselects in efficient way. I assume from log that you are using it to create a temporary table - it's a very nice trick. You may want to think of creating temp tables for some of those subqueries, set proper indexes related to your task and join them afterwards. I hope, that this query is not being sent to DB too frequently.

There is an useful EXPLAIN command in SQL. Try that documentation: here.

2. Hudge resultset

Depending on size of your sportsnews_log table, this one may occur you long times on writing to net:

SELECT /*!40001 SQL_NO_CACHE */ * FROM `sportnews_log`

@comment: I may be assuming wrong cause I do not know your DB, but I assume that sportsnews_log table may be big (let say 250k+ records). I'm pretty sure that you are not showing all those inputs out on site. SQL_NO_CACHE does not help to fasten that query, also using * is (a little) not advised - but may be necessary in your case. I may be thinking wrong in case you are periodically rewriting sportnews_log and keeping there 50~ rows, but I'm sure you would understand why I doubt in this. You probably are using ~20 records from that, so simple LIMIT with proper ORDER for newest inputs will do a HUDGE difference.

3. Frequent same queries

Lets treat this one in separate way:

SELECT `detail`, UNIX_TIMESTAMP(created_on) AS created_on
FROM (`sportnews_log`)
WHERE `severity` =  'info'
AND `source` =  'crawler'
ORDER BY `created_on` desc

It's more an example of #2 and probably a proper LIMIT will help a lot, but I assume this query fires up very frequently. There may be new solution for your but on one condition: those results are not required to be 100% actual, lets say a 5 minute offset before publication is OK. For that there are some cache mechanisms, that may help. In company I work we are using memcashed (have a look at "Memcasched users" list). PHP supports it well. Going with this, pseudocode for new solution would be:

declare RESULT
RESULT get from cache on key LAZY_UPDATE
if RESULT is false
    get use of your DB and set RESULT into query result
    set cache under LAZY_UPDATE key to value of RESULT for 5 minutes

return RESULT

This will make you stress your DB with that particular query only once per 5 minutes. If you are interested in it by far, take a look here.

Hey, thanks for your inputs. Could you please explain a bit what you mean by " this one is not too smart also" . Thanks for the link to the documentation — user2431436, Apr 24 '15 at 13:54
Hey, thanks alot for the clarification, yes it is indeed a big table. I will try to implement your recommendations :) — user2431436, Apr 24 '15 at 14:28
@user2431436 more updates in my post, hopes its helpful. Good luck! — yergo, Apr 25 '15 at 07:51

Website going down, cannot understand webserver process logs?

2 Answers2

1. Hudge stress on DB

2. Hudge resultset

3. Frequent same queries