Where is my time going?

[Pranav Prakash]

I use rsolr to add docs to Solr. I have logs set up just before adding doc and just after adding the docs. From my logs I see it like

I, [2011-10-05T06:55:12.283062 #9758]  INFO -- : Executing - SELECT * FROM docs_to_feed WHERE id >= 3012999 AND id < 3013999

I, [2011-10-05T06:55:13.851617 #9758]  INFO -- : Transcript fetch time: 1.55397701263428

I, [2011-10-05T06:55:13.876544 #9758]  INFO -- : Tags fetch time: 0.0247468948364258

I, [2011-10-05T06:55:13.876640 #9758]  INFO -- : 1.59356904029846s to fetch details from database. 3012999 to 3013999

I, [2011-10-05T06:55:13.876708 #9758]  INFO -- : Adding transcript, tags, building docs

I, [2011-10-05T06:55:15.272438 #9758]  INFO -- : 2.98936009407043s to build documents. 3012999 to 3013999

I, [2011-10-05T06:55:15.272568 #9758]  INFO -- : Adding to solr

I, [2011-10-05T06:55:49.287756 #9758]  INFO -- : 31.632997908695% Done

I, [2011-10-05T06:55:49.287891 #9758]  INFO -- : 37.0048229694366s to feed Solr. 3012999 to 3013999

However, If I look at Solr logs, I see them as 

INFO: {add=[3012999, 3013000, 3013001, 3013002, 3013003, 3013004, 3013006, 3013007, ... (515 adds)]} 0 5986

This clearly means that Solr is taking ~6s to add them. However, effectively my app takes 28s to add docs to Solr. Can anyone help me to understand where is this time going? 

My relevant section of code looks like

406           log.info("Adding to solr")

407           response = solr.add(docs)

408           log.info("#{(id_2*100.0)/last_id}% Done")

409           if response['responseHeader']['status'] != 0

410             log.fatal("Document ids  not sent")

411             #log.fatal(Solr::Request::AddDocument.new(docs_single).to_s)

412             log.close

413             exit

414           end

415           log.info("#{Time.now.to_f - starttime}s to feed Solr. #{id_1} to #{id_2}")

[matt mitchell]

Hmm, that would be hard to know without knowing more. How many docs are you adding at a time? What do they look like -- how much data? Do you have autoCommit turned on in your solrconfig.xml settings? Is this a local instance of Solr or is it living somewhere else? More details will help!

Matt

[Pranav Prakash]

The count of docs added is less than 1000 for sure. The exact count varies. They are XML docs with around 30 fields of which two are dynamic fields. My autocommit is turned off (There's no explicitly mentioned config in solrconfig.xml). The instance of Solr as well as the script feeding details are both on the same machine. Even the GC logs look fine, they take about 0.01s. 

I have also created a StackOverflow question for this - http://stackoverflow.com/questions/7706359/wheres-my-time-going-mysteriously

[Shairon Toledo]

Have you tried optimize the core?

--
You received this message because you are subscribed to the Google Groups "rsolr" group.
To view this discussion on the web visit https://groups.google.com/d/msg/rsolr/-/k80z5HejsPcJ.
To post to this group, send email to rs...@googlegroups.com.
To unsubscribe from this group, send email to rsolr+un...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/rsolr?hl=en.