[SERVER-5831] server stops processing requests during periodic flush Created: 12/May/12  Updated: 10/Dec/14  Resolved: 22/Nov/13

Status: Closed
Project: Core Server
Component/s: Concurrency
Affects Version/s: 2.0.4, 2.1.1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jared Rosoff Assignee: Andy Schwerin
Resolution: Duplicate Votes: 2
Labels: performance
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

multiple. have run on my mac and on aws.


Attachments: Microsoft Word sync delay analysis.xlsx     File writer.py    
Issue Links:
Related
related to SERVER-7973 Mongo should be able to reply to clie... Closed
Operating System: ALL
Participants:

 Description   

client is inserting records as quickly as it can.
seeing the insert rate drop to zero while background flushes happen.
have tested on 2.0.4 and 2.1.1 and see same behavior.

mongostat output:
...

insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time 
 23300      0      0      0       0       1       0   1.8g  6.01g   872m     93.7          0       0|0     0|1    12m     1k     2   15:59:24 
 22900      0      0      0       0       1       0   1.8g  6.01g   883m      105          0       0|0     0|1    12m     1k     2   15:59:25 
 23900      0      0      0       0       1       0   1.8g  6.01g   896m     98.7          0       0|0     0|1    12m     1k     2   15:59:26 
 22100      0      0      0       0       1       0   1.8g  6.01g   910m     96.4          0       0|0     0|1    11m     1k     2   15:59:27 
 18900      0      0      0       0       1       0   1.8g  6.01g   920m     95.7          0       0|0     0|1    10m     1k     2   15:59:28 
 16300      0      0      0       0       1       0   1.8g  6.01g   928m      106          0       0|0     0|0     8m     1k     2   15:59:29 
 17400      0      0      0       0       1       0   1.8g  6.01g   937m     99.2          0       0|0     0|1     9m     1k     2   15:59:30 
  9500      0      0      0       0       1       0   1.8g  6.01g   944m     52.6          0       0|0     0|1     5m     1k     2   15:59:31 
     0      0      0      0       0       1       0   1.8g  6.01g   944m        0          0       1|1     0|1    62b     1k     2   15:59:32 
     0      0      0      0       0       1       0   1.8g  6.01g   944m        0          0       1|1     0|1    62b     1k     2   15:59:33 
insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn       time 
 11600      0      0      0       0       1       1   2.8g  8.01g   949m      345          0       0|0     0|1     6m     1k     2   15:59:34 
  9300      0      0      0       0       1       0   2.8g  8.01g   956m     95.4          0       0|0     0|1     4m     1k     2   15:59:35 

You can see that during the few seconds before the flush happens, inserts drop to zero.

then about a minute later we see it again

16200      0      0      0       0       1       0   2.8g  8.01g  1.25g     93.1          0       0|0     0|1     8m     1k     2   16:00:24 
 16200      0      0      0       0       1       0   2.8g  8.01g  1.25g     95.3          0       0|0     0|1     8m     1k     2   16:00:25 
 17900      0      0      0       0       1       0   2.8g  8.01g  1.26g      109          0       0|0     0|1     9m     1k     2   16:00:26 
 17200      0      0      0       0       1       0   2.8g  8.01g  1.27g     96.9          0       0|0     0|1     9m     1k     2   16:00:27 
  8100      0      0      0       0       1       0   2.8g  8.01g  1.28g     60.6          0       0|0     0|1     4m     1k     2   16:00:28 
     0      0      0      0       0       1       0   2.8g  8.01g  1.28g        0          0       0|1     0|1    62b     1k     2   16:00:29 
  2700      0      0      0       0       1       1   2.8g  8.01g  1.28g      235          0       0|0     0|1     1m     1k     2   16:00:30 
 16200      0      0      0       0       1       0   2.8g  8.01g  1.29g     91.5          0       0|0     0|1     8m     1k     2   16:00:31 
 18900      0      0      0       0       1       0   2.8g  8.01g   1.3g      108          0       0|0     0|1    10m     1k     2   16:00:32 

I've attached the test program that recreates this.



 Comments   
Comment by Antoine Girbal [ 24/Aug/12 ]

Just for the record from an email thread..
I was thinking this could be due to the "journal commits under write lock" that happen while the disks are busy with the fsync.
If writing the journal buffer to disk takes a while then db will block.

Comment by Jared Rosoff [ 11/Jun/12 ]

Attaching test results showing impact of sync delay. I only ran each test for 2 minutes. Would probably be good to run each one for longer periods of time. First worksheet of attached xls shows summary of each syncdelay setting for same workload. Subsequent pages have the raw data.

Comment by Eliot Horowitz (Inactive) [ 14/May/12 ]

Maybe.
Smoothing it out makes it worse in some cases.
Jared - you can play with --syncdelay
--syncdelay 1 will probably have no pause, but worse overall performance for example.

Comment by Andy Schwerin [ 14/May/12 ]

Presumably we're the party making the disk busy. We might want, in the future, to at least smooth out this behavior, so that there aren't multi-second blocks in which no writes are possible.

Comment by Eliot Horowitz (Inactive) [ 14/May/12 ]

Not sure there is much we can do.
If the disk is busy its just busy.

Comment by Jared Rosoff [ 13/May/12 ]

Journal on separate device seems to fix it. Here's output on an ec2 machine with journal & data volumes on their own EBS volumes:

42700 0 0 0 0 1 0 1.95g 4.66g 1.6g 0 50.1 0 0|0 0|1 23m 1k 2 15:51:19
33400 0 0 0 0 1 0 1.95g 4.66g 1.62g 0 62.1 0 0|0 0|1 18m 1k 2 15:51:20
34000 0 0 0 0 1 1 1.95g 4.66g 1.64g 0 77.3 0 0|0 0|1 18m 1k 2 15:51:21
37900 0 0 0 0 1 0 1.95g 4.66g 1.66g 0 65.9 0 0|0 0|1 20m 1k 2 15:51:22
47000 0 0 0 0 1 0 1.95g 4.66g 1.68g 1 59.5 0 0|0 0|1 25m 1k 2 15:51:23

Comment by Eliot Horowitz (Inactive) [ 13/May/12 ]

Ah.
Could either be a block, or just the disk being super busy.
Can you try with journalling on but on a different device?
That should be the final test.

Comment by Jared Rosoff [ 13/May/12 ]

BTW, running with --nojournal makes this go away. Could the journal group commit be blocked on completion of the background flush?

output with mongod --nojournal

17500 0 0 0 0 1 0 5.95g 8.33g 1005m 103 0 0|0 0|1 9m 1k 2 21:46:55
11700 0 0 0 0 1 0 5.95g 8.33g 1012m 99.1 0 0|0 0|1 6m 1k 2 21:46:56
11800 0 0 0 0 1 0 5.95g 8.33g 1018m 99.5 0 0|0 0|1 6m 1k 2 21:46:57
21600 0 0 0 0 1 0 5.95g 8.33g 1.01g 98.8 0 0|0 0|1 11m 1k 2 21:46:58
15000 0 0 0 0 1 0 5.95g 8.33g 1.01g 99.3 0 0|0 0|1 8m 1k 2 21:46:59
12500 0 0 0 0 1 1 5.95g 8.33g 1.02g 98.7 0 0|0 0|1 6m 1k 2 21:47:00
58100 0 0 0 0 1 0 5.95g 8.33g 1.05g 86.2 0 0|0 0|1 31m 1k 2 21:47:01

Comment by Jared Rosoff [ 13/May/12 ]

Are the db.serverStatus().backgroundFlushing stats useful?

Here was the mongostat output during the pause:

14000 0 0 0 0 1 0 3.95g 10.3g 2.29g 96.7 0 0|0 0|1 7m 1k 3 21:17:03
11300 0 0 0 0 1 0 3.95g 10.3g 2.29g 95.6 0 0|0 0|1 6m 1k 3 21:17:04
0 0 0 0 0 1 0 3.95g 10.3g 2.29g 0 0 0|1 0|1 62b 1k 3 21:17:05
8400 0 0 0 0 1 1 3.95g 10.3g 2.3g 204 0 0|0 0|1 4m 1k 3 21:17:06
14000 0 0 0 0 1 0 3.95g 10.3g 2.31g 98.6 0 0|0 0|1 7m 1k 3 21:17:07

Here was the db.serverStatus().backgroundFlushing immediately after the pause

> db.serverStatus().backgroundFlushing
{
"flushes" : 144,
"total_ms" : 32823,
"average_ms" : 227.9375,
"last_ms" : 1817,
"last_finished" : ISODate("2012-05-13T04:17:05.776Z")
}

Comment by Andy Schwerin [ 13/May/12 ]

Interesting. 2 questions. 1, is it possible to tell how long the flushAll() operation takes? 2, does it even make sense to periodically flush like this when durability is enabled? The durability subsystem separately handles flushing the shared view to disk and committing journal writes, leaving open the question of why the background flush thread would even be necessary with durability.

Comment by Jared Rosoff [ 13/May/12 ]

two writer processes:

19300 0 0 0 0 1 0 1.95g 6.32g 1.26g 105 0 0|1 0|2 10m 1k 3 20:05:01
18800 0 0 0 0 1 0 1.95g 6.32g 1.27g 93.3 0 0|1 0|2 10m 1k 3 20:05:02
19400 0 0 0 0 1 0 1.95g 6.32g 1.28g 94.8 0 0|1 0|2 10m 1k 3 20:05:03
0 0 0 0 0 1 0 1.95g 6.32g 1.28g 0 0 0|2 0|2 62b 1k 3 20:05:04
insert query update delete getmore command flushes mapped vsize res locked % idx miss % qr|qw ar|aw netIn netOut conn time
0 0 0 0 0 1 0 1.95g 6.32g 1.28g 0 0 1|2 0|2 62b 1k 3 20:05:05
8300 0 0 0 0 1 0 1.95g 6.32g 1.28g 310 0 0|1 0|2 4m 1k 3 20:05:06
16000 0 0 0 0 1 1 1.95g 6.32g 1.29g 95.2 0 0|1 0|2 8m 1k 3 20:05:08
17400 0 0 0 0 1 0 1.95g 6.32g 1.3g 92.5 0 0|1 0|2 9m 1k 3 20:05:09

three writer processes:

10100 0 0 0 0 1 0 3.95g 10.3g 1.89g 93.3 0 0|2 0|3 5m 1k 4 20:08:02
12400 0 0 0 0 1 0 3.95g 10.3g 1.9g 123 0 0|2 0|3 6m 1k 4 20:08:03
6000 0 0 0 0 1 0 3.95g 10.3g 1.9g 68.8 0 0|2 0|3 3m 1k 4 20:08:04
0 0 0 0 0 1 0 3.95g 10.3g 1.9g 0 0 1|3 0|3 62b 1k 4 20:08:05
0 0 0 0 0 1 0 3.95g 10.3g 1.9g 0 0 1|3 0|3 62b 1k 4 20:08:06
3200 0 0 0 0 1 1 3.95g 10.3g 1.9g 307 0 0|2 0|3 1m 1k 4 20:08:07
9600 0 0 0 0 1 0 3.95g 10.3g 1.91g 92.8 0 0|2 0|3 5m 1k 4 20:08:08

Comment by Scott Hernandez (Inactive) [ 13/May/12 ]

Can you run more than one process and see if the behavior changes?

Comment by Jared Rosoff [ 13/May/12 ]

ext4.

Comment by Eliot Horowitz (Inactive) [ 13/May/12 ]

What linux filesystem?

Generated at Thu Feb 08 03:10:00 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.