Details
-
Question
-
Resolution: Done
-
Major - P3
-
None
-
2.6.12
-
None
-
MongoDB 2.6.12
Ubuntu 14.04 w/4.4 kernel
No virtualization, plain iron
Description
We're running MongoDB 2.6.12 (yes, I know it's a fairly old version, but there is no real reason to upgrade for this instance), but I believe that the question might be there for modern versions as well.
While most of our databases are stored on SSDs, this particular cluster has only journals and config servers stored on SSDs, the datafiles themselves are located on nearline SAS spinning disks (spanning about 80 of them) to cut costs. The data is written in a "streaming" fashion – mostly the data is inserted, and occasionally (<1% of inserts) – deleted, so it's almost an append-only database with relatively low fragmentation.
Unfortunately we discovered that something that happens before datafile allocation leads to strange slowdowns. We use ext4 for old shards and xfs for new ones, but there is no real difference. Just before datafile is allocated, the usual sub-500msec insert time spikes to 5-25 seconds per operation. Is this an extent file management issue that tries to find space in previous extents before growing and our fragmentation analysis is wrong?
A typical excerpt from the log follows:
2016-10-17T13:18:25.797+0300 [FileAllocator] done allocating datafile /mnt/data5/a.1570, size: 2047MB, took 0.092
|
secs
|
2016-10-17T13:18:25.815+0300 [conn859391] insert a.fs.chunks query: { _id: ObjectId('5804a562f2ac4910f0306ed4'), files_id: 272245892
|
5734559744, n: 0, data: BinData(0, FFD8FFE000104A46494600010101000000000000FFDB00430002020202020102020202030202030306040303030307050
|
504060807090808070808090A0D0B090A0C0A08080B...) } ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:15780713 15762ms
|
2016-10-17T13:18:25.815+0300 [conn859391] command a.$cmd command: insert { insert: "fs.chunks", documents: [ { _id: ObjectId('5804a5
|
62f2ac4910f0306ed4'), files_id: 2722458925734559744, n: 0, data: BinData(0, FFD8FFE000104A46494600010101000000000000FFDB004300020202
|
02020102020202030202030306040303030307050504060807090808070808090A0D0B090A0C0A08080B...) } ], writeConcern: { w: 1 }, ordered: true,
|
metadata: { shardName: "driveFS-1", shardVersion: [ Timestamp 313546000|0, ObjectId('51793868331d54dfcf8e0032') ], session: 0 } } n
|
toreturn:1 keyUpdates:0 numYields:0 locks(micros) w:130 reslen:140 15762ms
|
2016-10-17T13:18:25.816+0300 [conn2108532] getmore local.oplog.rs query: { ts: { $gte: Timestamp 1476669897000|3 } } cursorid:188093
|
731175 ntoreturn:0 keyUpdates:0 numYields:1 locks(micros) r:336 nreturned:1 reslen:82619 16515ms
|
2016-10-17T13:18:25.816+0300 [conn2108409] getmore local.oplog.rs query: { ts: { $gte: Timestamp 1476669897000|3 } } cursorid:187931
|
282777 ntoreturn:0 keyUpdates:0 numYields:1 locks(micros) r:111 nreturned:1 reslen:82619 16515ms
|
2016-10-17T13:18:25.845+0300 [conn74996] insert a.fs.chunks query: { _id: ObjectId('5804a5631866cf15dcad4bcc'), files_id: 2145998173
|
431136256, n: 0, data: BinData(0, FFD8FFE000104A46494600010101000000000000FFDB004300020202020201020202020302020303060403030303070505
|
04060807090808070808090A0D0B090A0C0A08080B...) } ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:45631 14147ms
|
2016-10-17T13:18:25.846+0300 [conn74996] command a.$cmd command: insert { insert: "fs.chunks", documents: [ { _id: ObjectId('5804a56
|
31866cf15dcad4bcc'), files_id: 2145998173431136256, n: 0, data: BinData(0, FFD8FFE000104A46494600010101000000000000FFDB0043000202020
|
2020102020202030202030306040303030307050504060807090808070808090A0D0B090A0C0A08080B...) } ], writeConcern: { w: 1 }, ordered: true,
|
metadata: { shardName: "driveFS-1", shardVersion: [ Timestamp 313546000|0, ObjectId('51793868331d54dfcf8e0032') ], session: 0 } } nt
|
oreturn:1 keyUpdates:0 numYields:0 locks(micros) w:274 reslen:140 14148ms
|
2016-10-17T13:18:25.882+0300 [conn1018147] insert a.fs.chunks query: { _id: ObjectId('5804a5656248ad146439e561'), files_id: 25783437
|
37658703872, n: 0, data: BinData(0, FFD8FFE000104A46494600010101000000000000FFDB0043000202020202010202020203020203030604030303030705
|
0504060807090808070808090A0D0B090A0C0A08080B...) } ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:72293 12337ms
|
2016-10-17T13:18:25.883+0300 [conn1018147] command a.$cmd command: insert { insert: "fs.chunks", documents: [ { _id: ObjectId('5804a
|
5656248ad146439e561'), files_id: 2578343737658703872, n: 0, data: BinData(0, FFD8FFE000104A46494600010101000000000000FFDB00430002020
|
202020102020202030202030306040303030307050504060807090808070808090A0D0B090A0C0A08080B...) } ], writeConcern: { w: 1 }, ordered: true
|
, metadata: { shardName: "driveFS-1", shardVersion: [ Timestamp 313546000|0, ObjectId('51793868331d54dfcf8e0032') ], session: 0 } }
|
ntoreturn:1 keyUpdates:0 numYields:0 locks(micros) w:253 reslen:140 12338ms
|
2016-10-17T13:18:25.883+0300 [conn63069] insert a.fs.chunks query: { _id: ObjectId('5804a567f2ac4910f0306ef5'), files_id: 1425422233
|
051856896, n: 0, data: BinData(0, FFD8FFE000104A46494600010101000000000000FFDB004300020202020201020202020302020303060403030303070505
|
04060807090808070808090A0D0B090A0C0A08080B...) } ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:465 10364ms
|
2016-10-17T13:18:25.883+0300 [conn63069] command a.$cmd command: insert { insert: "fs.chunks", documents: [ { _id: ObjectId('5804a56
|
7f2ac4910f0306ef5'), files_id: 1425422233051856896, n: 0, data: BinData(0, FFD8FFE000104A46494600010101000000000000FFDB0043000202020
|
2020102020202030202030306040303030307050504060807090808070808090A0D0B090A0C0A08080B...) } ], writeConcern: { w: 1 }, ordered: true,
|
metadata: { shardName: "driveFS-1", shardVersion: [ Timestamp 313546000|0, ObjectId('51793868331d54dfcf8e0032') ], session: 0 } } nt
|
oreturn:1 keyUpdates:0 numYields:0 locks(micros) w:64 reslen:140 10364ms
|
2016-10-17T13:18:26.328+0300 [conn859389] insert a.fs.chunks query: { _id: ObjectId('5804a5706cdf41115886dfb5'), files_id: 229011336
|
1506992128, n: 0, data: BinData(0, FFD8FFE000104A46494600010101000000000000FFDB00430002020202020102020202030202030306040303030307050
|
504060807090808070808090A0D0B090A0C0A08080B...) } ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:102245 1636ms
|
2016-10-17T13:18:26.329+0300 [conn859389] command a.$cmd command: insert { insert: "fs.chunks", documents: [ { _id: ObjectId('5804a5
|
706cdf41115886dfb5'), files_id: 2290113361506992128, n: 0, data: BinData(0, FFD8FFE000104A46494600010101000000000000FFDB004300020202
|
02020102020202030202030306040303030307050504060807090808070808090A0D0B090A0C0A08080B...) } ], writeConcern: { w: 1 }, ordered: true,
|
metadata: { shardName: "driveFS-1", shardVersion: [ Timestamp 313546000|0, ObjectId('51793868331d54dfcf8e0032') ], session: 0 } } n
|
toreturn:1 keyUpdates:0 numYields:0 locks(micros) w:243 reslen:140 1637ms
|