How can my Ruby "Time.now" timings be so low when my "ping" timings are so high?

Question

I'm using MongoDB for the first time and trying to time its performance. I'm running ruby on a VirtualBox Ubuntu 9.10 guest with a Windows 7 64-bit host. MongoDB is on a remote host, not on my lan buit somewhere in the internet cloud.

Here's my code:

time1 = Time.now
rows = coll.find(some_criteria)
puts ((Time.now - time1) * 1000).to_s

The problem is, the time is so small, I don't believe what I'm seeing. I'm seeing times around 50, 100, 200 MICROseconds, while ping times between my computer and the remote mongo computer are around 40 MILLIseconds. Am I misunderstanding the units? How can my timings be so low when the ping is so high?

Answer 1

You could start a packet sniffer, start irb, and then issue some test commands one line at a time, but you already seem to have accurately analyzed its dynamic behavior.

So, I suppose you got coll with something like coll = db.collection_names? And I suppose coll must be an Enumerable?

If so, nothing really needs to happen in that call except the return of an object with an each method. Perhaps nothing actually does happen until you ask for something from the Enumerable.

You might try:

time1 = Time.now
rows = coll.find(some_criteria)
o = rows.first
puts ((Time.now - time1) * 1000).to_s

This won't necessarily take any longer. It's possible that the work was done when db.collection_names was called. The irb test, from the top, might shed some light on the issue...

Answer 2

Simple answer: this line isn't doing what you expect:

rows = coll.find(some_criteria)

specifically, it's not communicating with the server.