Where's my time going mysteriously?

I have a ruby script that uses rsolr rubygem to generate XMLs and POST them to Apache Solr (javadoc Update Command) surfaced by Jetty Server. My script logs certain time using the following code

405       unless docs.empty?
406         begin
407           log.info("Adding to solr")
408           response = solr.add(docs)
409           log.info("#{(id_2*100.0)/last_id}% Done")
410           if response['responseHeader']['status'] != 0
411             log.fatal("Document ids  not sent")
412             #log.fatal(Solr::Request::AddDocument.new(docs_single).to_s)
413             log.close
414             exit
415           end
416           log.info("#{Time.now.to_f - starttime}s to feed Solr. #{id_1} to #{id_2}")
417         rescue Exception => e
418           log.fatal("Document ids not sent => ")
419           #log.fatal(Solr::Request::AddDocument.new(docs_single).to_s)
420           #log.fatal(docs)
421           log.close   
422           exit
423         end

The log generated goes like

I, [2011-10-09T15:03:42.617048 #30092]  INFO -- : Executing - SELECT * FROM solr_feeddata_2 WHERE id >= 5879999 AND id < 5881999
I, [2011-10-09T15:03:44.086661 #30092]  INFO -- : External Data1 fetch time: 1.45462989807129
I, [2011-10-09T15:03:44.109514 #30092]  INFO -- : External Data2 fetch time: 0.0226790904998779
I, [2011-10-09T15:03:44.109611 #30092]  INFO -- : 1.49255704879761s to fetch details from database. 5879999 to 5881999
I, [2011-10-09T15:03:44.109702 #30092]  INFO -- : Adding data1, data2, building docs
I, [2011-10-09T15:03:45.912603 #30092]  INFO -- : 3.29554414749146s to build documents. 5879999 to 5881999
I, [2011-10-09T15:03:45.912730 #开发者_如何转开发30092]  INFO -- : Adding to solr
I, [2011-10-09T15:04:24.797620 #30092]  INFO -- : 61.180855194502% Done
I, [2011-10-09T15:04:24.797744 #30092]  INFO -- : 42.180694103241s to feed Solr. 5879999 to 5881999

According to this log, Solr took (42.18 - 3.29 - 1.49 - 2) 35.4s to respond. (See below comment)

At the same time my Solr log for this particular update goes like

INFO: {add=[5879999, 5880000, 5880001, 5880002, 5880003, 5880004, 5880005, 5880007, ... (1468 adds)]} 0 5780
Oct 9, 2011 3:04:24 PM org.apache.solr.core.SolrCore execute
INFO: [core0] webapp=/solr path=/update params={wt=ruby} status=0 QTime=5780 
Oct 9, 2011 3:04:42 PM org.apache.solr.update.processor.LogUpdateProcessor finish

This clearly shows that Solr took 5.78s to add the docs, initiate response send and closed the log updater.

Both the services run on same machine, inside the network, and their ping summary is

rtt min/avg/max/mdev = 0.008/0.010/0.022/0.006 ms

This pattern is clearly visible for every batch data processed. Despite my sincere efforts to get this mystery out, I am not able to get the reason for this behavior.

My Solr mergeFactor is 10, autoCommit is off.