what is mongodb telling me when it logs an update?

Question

After several minutes of a large program that pushes a lot of data into mongo, my log starts to show a message for (I guess) each update. This seems awfully noisy, is there some special reason it feels the need to do this?

Tue Jun  5 14:32:37 [conn3] update benchmark.entity  
 query: { corefEntityId: "45-LOCATION" } 
 update: { $set: { corefEntityId: "45-LOCATION", type: "Location" },
 $push: { indocs: { docid: "cfcc403b-714f-4c5d-8507-ccb5b6354654", 
   ordinal: 26, label: "United States", mentions: [ "United States" ] } }, 
   $addToSet: { allMentions: { $each: [ "United States" ] } }, 
   $inc: { documentCount: 1 } } 116ms

As a perhaps more answerable footnote, I wonder: is an 'upsert' that adds to some internal document faster or slower than a plain insert into some other collection of the internal document as a top-level document?

Answer 1

I think you meant upsert rather than upstart (upstart being a type of job on an Ubuntu system). Upsert means "update the document if present; insert (a single document) if missing". MongoDB determines that the document is missing solely via examining the criteria document you pass to it.

That query to determine whether the document exists is likely the slow part here. You should run an explain on just the find to determine if it is using indexes correctly and is as efficient as it should be:

http://www.mongodb.org/display/DOCS/Explain

If it is not using an index then you should add one to speed things up. Depending on whether this example is typical of your query plan I would expect that an index on "corefEntityId" would be a good idea at a minimum. If the find is more complex in other cases you may want to look into a compound index and use hint to see which is optimal:

http://www.mongodb.org/display/DOCS/Optimization#Optimization-Hint

In terms of the logging - when it logs a query like you have seen in your example, the reason is because the default "slowms" value is 100. That is, MongoDB will log every query that takes longer than 100ms to complete. This can be adjusted:

http://www.mongodb.org/display/DOCS/Database+Profiler#DatabaseProfiler-EnablingProfiling

If you wanted to set it to 200ms for example:

db.setProfilingLevel(1,200)