18G journal, high cpu every 10 seconds

[Avery Fay]

Hi,

One of our mongo machines has a 18G journal. Also, every 10 seconds
mongo uses 100% cpu (on one core) for about 5 seconds).

ls -lh /var/lib/mongo/data/journal

-rw------- 1 live live 1.1G 2011-07-11 14:58 j._25
-rw------- 1 live live  18G 2011-07-11 16:11 j._26
-rw------- 1 live live   88 2011-07-11 16:09 lsn
-rw------- 1 live live 9.1G 2011-07-08 00:28 prealloc.2

also 9G prealloc?

end of grep journal /var/log/mongo/mongod.log

Sat Jul  9 15:19:31 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._10
Sat Jul  9 18:01:58 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._11
Sat Jul  9 21:05:06 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._12
Sun Jul 10 00:26:25 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._13
Sun Jul 10 03:33:24 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._14
Sun Jul 10 07:30:31 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._15
Sun Jul 10 11:35:30 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._16
Sun Jul 10 15:17:09 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._17
Sun Jul 10 18:11:36 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._18
Sun Jul 10 21:01:40 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._19
Mon Jul 11 00:35:42 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._20
Mon Jul 11 03:47:35 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._21
Mon Jul 11 08:13:53 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._22
Mon Jul 11 11:44:32 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._23
Mon Jul 11 14:58:51 [dur] old journal file will be removed:
/var/lib/mongo/data/journal/j._24

Nothing past that mentions journal.

Sample output of vmstat 1, show cpu spike (verified to be mongod via top):

 0  0   9456  89752 125736 15190172    0    0   668   120 2657 4207  1  1 95  3
 0  0   9456  88388 125736 15190400    0    0   376   180 2269 3617  2  1 94  3
 1  0   9456  88884 125736 15190976    0    0   264   104 2667 4173  1  1 96  2
 2  0   9456  88264 125736 15190996    0    0   372    72 2835 4283  4  1 94  2
 1  0   9456  89124 125736 15191316    0    0   192    88 3791 4457 26  2 70  1
 3  0   9456  87620 125736 15192184    0    0   824   104 3584 4138 24  2 71  3
 1  0   9456  90976 125720 15187764    0    0   560   392 4651 4556 24  1 72  3
 1  0   9456  91844 125720 15187772    0    0   300    64 3578 4214 25  2 72  2
 0  0   9456  90852 125720 15188276    0    0   436    88 3095 4245 13  2 83  2
 1  0   9456  90240 125720 15188960    0    0   664    96 2996 4625  2  1 95  2
 0  0   9456  89620 125720 15189028    0    0   112   120 2570 4333  3  1 96  1
 0  1   9456  89248 125720 15189468    0    0   388   424 2595 4367  1  0 96  3
 0  1   9456  89372 125720 15190228    0    0   628   176 2484 4109  2  1 96  1
 0  1   9456  88752 125720 15190516    0    0   420    88 2461 4073  1  0 95  3
 0  0   9456  88628 125720 15190964    0    0   444   128 2512 4063  2  0 97  2
 0  0   9456  88008 125720 15191704    0    0   736   104 2626 4133  2  0 95  2
 0  0   9456  92340 125716 15186908    0    0   368  1928 3067 4535  2  1 93  4
 0  0   9456  92092 125716 15187468    0    0   296   104 2451 4085  2  0 95  2
 0  0   9456  90852 125716 15187516    0    0   192    88 2625 4276  1  1 96  2
 1  0   9456  91348 125716 15188156    0    0   300    80 2975 4177 13  0 86  1
 2  0   9456  90844 125716 15188172    0    0   252    64 3668 4491 26  1 72  1
 2  0   9456  90844 125716 15188696    0    0   268  3188 4734 4928 23  2 70  4
 1  0   9456  90472 125716 15188968    0    0   272    48 3788 4309 24  2 72  3
 1  0   9456  89728 125716 15189316    0    0   396    72 3532 4223 22  2 73  2
 1  1   9456  89852 125716 15189388    0    0   208   112 2921 4258  6  1 91  2
 1  0   9456  89240 125716 15189940    0    0   300   340 2908 4605  3  1 94  3
 0  0   9456  89992 125732 15189956    0    0   248   968 3286 4822  1  1 96  2

What's going on here?

btw, this is 1.8.2

Avery

[mathias]

Were you building an index?

We recycle journal files to be prealloc files which is why you are
seeing a 9GB file there (and could explain the 18GB file). I've opened
a ticket to truncate the file down to 2GB before recycling:
https://jira.mongodb.org/browse/SERVER-3412

[Avery Fay]

Well, it's hard to say. It seems the 18GB journal file persists even
across server restarts, so while we weren't building an index
yesterday it's quite possible that it was created during an index
build (this machine is a new replica member that was initiated with a
normal sync so there would have been an index build last week
sometime).

[axlfu]

I remember Scott and Eliot had said the most of journal file is 3GB,
why here mongodb use so much disk space?

[Eliot Horowitz]

There is a bug that can cause it to get larger sometimes:
https://jira.mongodb.org/browse/SERVER-3412

> --
> You received this message because you are subscribed to the Google Groups "mongodb-user" group.
> To post to this group, send email to mongod...@googlegroups.com.
> To unsubscribe from this group, send email to mongodb-user...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
>
>