Creating index slowly?

[Hanson Lu]

My collection currently has 40M records, and  i create a new compound index for it

The speed is 2512rec/sec. The insert speed for the collection is larger than 5k.

Is it normal? 

        "inprog" : [

                {

                        "opid" : 6,

                        "active" : true,

                        "lockType" : "write",

                        "waitingForLock" : false,

                        "secs_running" : 2081,

                        "op" : "insert",

                        "ns" : "cidb.system.indexes",

                        "query" : {

                        },

                        "client" : "127.0.0.1:57013",

                        "desc" : "conn",

                        "threadId" : "0x7f4ec0ff9710",

                        "connectionId" : 1,

                        "msg" : "bg index build 5228947/41882393 12%",

                        "progress" : {

                                "done" : 5228947,

                                "total" : 41882393

                        },

                        "numYields" : 814

                }

The collection has field like

{

   sender: "X",
   receiver:"Y",

   type:"TEXT",

   sendDate:"20120801020100"

  ...

}

I create index {sender:1,type:1,sendDate:-1}.

Th related topic i post is 

(http://groups.google.com/forum/?fromgroups=#!topic/mongodb-user/z68SDBt-wqk)

Hanson Lu 

[Hanson Lu]

The log show warning 

  "Tue Aug 21 07:09:27 [conn1] DR101 latency warning on journal file open 6605ms"

Data stored disk is local, not NFS.

[matts]

Can you run iostat during the insert operation and post the results here?

[Hanson Lu]

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda               0.00   599.50    0.00  264.68     0.00     1.81    14.02   280.64 1141.55   3.76  99.50

sr0               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda               0.00  1431.00    0.00  222.00     0.00     9.83    90.68   284.18 1099.77   4.51 100.20

sr0               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda               0.00   119.90    0.00  250.75     0.00     1.41    11.56   282.28 1240.17   3.98  99.70

sr0               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

[matts]

I assume that you created the index with background equals true? (so it is creating the index in the background while you are inserting 5k records)

What version of the system are you running?

your disks appear to be fully saturated.

[Hanson Lu]

Yes, i created the index with background option. There is no inserting operation during creating index. 

 .

[Hanson Lu]

MongoDB version is 2.0.2,  linux 64bit 

[matts]

Can you try turning off background index creation and seeing if the latency warning still appears?

[Hanson Lu]

Sorry reply late , i just notice your post.

I turn off the background index creating, it seems no latency report  and i feel that  the speed is about twice as fast of the background indexing. 

This is iostat result  that remove the background option. 

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda               0.50   103.50   96.00   33.50    21.52     0.53   348.69     2.56   19.78   2.69  34.80

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

           4.79    0.00    0.47    0.05    0.21   94.49

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda               0.50     6.97   48.26    9.95    10.62     0.07   375.86     0.48    8.24   1.95  11.34

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

           5.18    0.00    0.53    0.81    0.44   93.04

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda               3.00  5998.50  250.00   11.00    55.68     2.22   454.34    28.98   12.83   2.43  63.40

I tested  IO performance of the disk, it shows  max wMB is about 40M, 

So i wonder why creating indexing with background option, the wMB is  low (9.83)?

the Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda                      0.00  1431.00    0.00  222.00     0.00     9.83    90.68   284.18 1099.77   4.51 100.20

[Hanson Lu]

More iostat  data for creating indexing with no background option 

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda               2.99  5867.66   42.79   82.09    10.21    22.24   532.18    79.02  612.02   7.86  98.11

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

           5.04    0.00    0.61    1.34    0.55   92.46

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda               1.00   140.50  242.50   37.50    53.56     1.75   404.59     3.06   62.91   2.88  80.60

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

           8.52    0.00    0.22    0.09    0.22   90.96

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda                0.00     1.00   70.00    0.50    15.27     0.01   443.74     0.24    3.38   1.93  13.60

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

           4.53    0.00    0.29    0.10    0.22   94.87

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda                 1.49  5875.12   50.25   20.90    11.23     2.29   389.31    18.04   19.94   3.97  28.26

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

           2.37    0.00    0.47    4.02    0.37   92.76

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util

sda                2.49    63.68   89.55   83.58    20.40    21.31   493.36    65.04  471.61   5.77  99.90

[Hanson Lu]

I saw two latency report at the end of creating 

Tue Sep 11 06:33:28 [conn1]      done building bottom layer, going to commit

Tue Sep 11 06:34:26 [conn1] old journal file will be removed: /home/user/mongo/mongodb/bin/../data/db/journal/j._1

Tue Sep 11 06:34:48 [conn1] DR101 latency warning on journal file open 18122ms

Tue Sep 11 06:36:34 [conn1] old journal file will be removed: /home/user/mongo/mongodb/bin/../data/db/journal/j._2

Tue Sep 11 06:36:40 [conn1] DR101 latency warning on journal file open 255ms

Tue Sep 11 06:36:47 [conn1] build index done 68885138 records 4109.42 secs

[David Hows]

Hi Hanson,

From the iostat output and the logs it would seem your disk hit a very heavy load, probably due to the removal of journal files and creation of index at the same time.

The last iostat you posted shows very heavy disk utilisation.

Are you still seeing these issues?

Cheers,

David

[Hanson Lu]

Hi David ,

 The both have heavy io utilization. But i noticed that the wMB/s(iostat) of indexing without background option is higher than that of indexing with background option. 

 

 So i think whether the writing operation is not optimized well for background indexing. 

 Actually the speed of background indexing is more worse than the data in my last post.

 It took more than 5 hours to create background index(40M records), only about 1-hour to create the same index without background option.

Regards 

Hanson

[David Hows]

Hi Hanson,

What you speak of is the tradeoff involved when using the background option.

If you create without background, it will go faster but will consume more IO.

If you create with background, it will take longer but consume less resources.

Hope that clears things up.

David