Куда загадочным образом уходит мое время? - PullRequest
Новая
       18

Куда загадочным образом уходит мое время?

0 голосов
/ 10 октября 2011

У меня есть скрипт ruby, который использует rsolr rubygem для генерации XML-файлов и отправки их в Apache Solr ( Команда обновления javadoc ), обнаруженная на сервере Jetty. Мой скрипт регистрирует определенное время, используя следующий код 

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

Сгенерированный журнал выглядит как 

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

Согласно этому журналу, Solr потребовал (42,18 - 3,29 - 1,49 - 2) 35,4 с, чтобы ответить. (См. Комментарий ниже)

В то же время мой журнал Solr для этого конкретного обновления выглядит как 

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

Это ясно показывает, что Solr потребовалось 5,78 с, чтобы добавить документы, инициировать отправку ответа и закрыть средство обновления журнала.

Обе службы работают на одной машине внутри сети, и их суммарный пинг равен 

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

Этот шаблон хорошо виден для каждой обрабатываемой партии данных. Несмотря на мои искренние попытки раскрыть эту тайну, я не могу понять причину такого поведения.

Мой Солр mergeFactor равен 10, autoCommit выключен.

...