I attach chart which presents cpu usage. Solr 3.5 uses almost all cpu
(left side of chart).
at the begining of chart there was about 60rps and about 100rps
(before turning off solr 3.5). Then there was 1.4 turned on with
100rps.
--
Pawel
On Wed, Nov 30, 2011 at 9:07 AM, Pawel Rog <pawelro...@gmail.com> wrote:
> * 1st question (ls from index directory)
>
> solr 1.4
>
> -rw-r--r-- 1 user user 2180582 Nov 30 07:26 _3g1_cf.del
> -rw-r--r-- 1 user user 5190652802 Nov 28 17:57 _3g1.fdt
> -rw-r--r-- 1 user user 139556724 Nov 28 17:57 _3g1.fdx
> -rw-r--r-- 1 user user 4963 Nov 28 17:56 _3g1.fnm
> -rw-r--r-- 1 user user 1879006175 Nov 28 18:01 _3g1.frq
> -rw-r--r-- 1 user user 513919573 Nov 28 18:01 _3g1.prx
> -rw-r--r-- 1 user user 2745451 Nov 28 18:01 _3g1.tii
> -rw-r--r-- 1 user user 218731810 Nov 28 18:01 _3g1.tis
> -rw-r--r-- 1 user user 275268 Nov 30 07:26 _3uu_1a.del
> -rw-r--r-- 1 user user 666375513 Nov 30 03:35 _3uu.fdt
> -rw-r--r-- 1 user user 17616636 Nov 30 03:35 _3uu.fdx
> -rw-r--r-- 1 user user 4884 Nov 30 03:35 _3uu.fnm
> -rw-r--r-- 1 user user 243847897 Nov 30 03:35 _3uu.frq
> -rw-r--r-- 1 user user 64791316 Nov 30 03:35 _3uu.prx
> -rw-r--r-- 1 user user 545317 Nov 30 03:35 _3uu.tii
> -rw-r--r-- 1 user user 42993472 Nov 30 03:35 _3uu.tis
> -rw-r--r-- 1 user user 1178 Nov 30 07:26 _3wj_1.del
> -rw-r--r-- 1 user user 2813124 Nov 30 07:26 _3wj.fdt
> -rw-r--r-- 1 user user 74852 Nov 30 07:26 _3wj.fdx
> -rw-r--r-- 1 user user 2175 Nov 30 07:26 _3wj.fnm
> -rw-r--r-- 1 user user 911051 Nov 30 07:26 _3wj.frq
> -rw-r--r-- 1 user user 4 Nov 30 07:26 _3wj.nrm
> -rw-r--r-- 1 user user 285405 Nov 30 07:26 _3wj.prx
> -rw-r--r-- 1 user user 7951 Nov 30 07:26 _3wj.tii
> -rw-r--r-- 1 user user 624702 Nov 30 07:26 _3wj.tis
> -rw-r--r-- 1 user user 35859092 Nov 30 07:26 _3wk.fdt
> -rw-r--r-- 1 user user 958148 Nov 30 07:26 _3wk.fdx
> -rw-r--r-- 1 user user 4104 Nov 30 07:26 _3wk.fnm
> -rw-r--r-- 1 user user 12228212 Nov 30 07:26 _3wk.frq
> -rw-r--r-- 1 user user 3438508 Nov 30 07:26 _3wk.prx
> -rw-r--r-- 1 user user 58672 Nov 30 07:26 _3wk.tii
> -rw-r--r-- 1 user user 4621519 Nov 30 07:26 _3wk.tis
> -rw-r--r-- 1 user user 0 Nov 30 07:27
> lucene-9445a367a714cc9bf70d0ebdf83b9e01-write.lock
> -rw-r--r-- 1 user user 1010 Nov 30 07:26 segments_2tr
> -rw-r--r-- 1 user user 20 Nov 17 14:06 segments.gen
>
> solr 3.5 (dates are older - because I turned off feeding 3.5 instance)
>
> -rw-r--r-- 1 user user 2188376 Nov 29 13:10 _2x_6g.del
> -rw-r--r-- 1 user user 4955406209 Nov 28 17:38 _2x.fdt
> -rw-r--r-- 1 user user 140054140 Nov 28 17:38 _2x.fdx
> -rw-r--r-- 1 user user 4852 Nov 28 17:37 _2x.fnm
> -rw-r--r-- 1 user user 1845719205 Nov 28 17:42 _2x.frq
> -rw-r--r-- 1 user user 497871055 Nov 28 17:42 _2x.prx
> -rw-r--r-- 1 user user 3006635 Nov 28 17:42 _2x.tii
> -rw-r--r-- 1 user user 230304265 Nov 28 17:42 _2x.tis
> -rw-r--r-- 1 user user 50128 Nov 29 13:10 _5s_48.del
> -rw-r--r-- 1 user user 116159640 Nov 29 00:25 _5s.fdt
> -rw-r--r-- 1 user user 3206268 Nov 29 00:25 _5s.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 00:25 _5s.fnm
> -rw-r--r-- 1 user user 44556139 Nov 29 00:25 _5s.frq
> -rw-r--r-- 1 user user 11405232 Nov 29 00:25 _5s.prx
> -rw-r--r-- 1 user user 149965 Nov 29 00:25 _5s.tii
> -rw-r--r-- 1 user user 11662163 Nov 29 00:25 _5s.tis
> -rw-r--r-- 1 user user 63191 Nov 29 13:10 _97_1o.del
> -rw-r--r-- 1 user user 145482785 Nov 29 08:08 _97.fdt
> -rw-r--r-- 1 user user 4042300 Nov 29 08:08 _97.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 08:08 _97.fnm
> -rw-r--r-- 1 user user 55361299 Nov 29 08:08 _97.frq
> -rw-r--r-- 1 user user 14181208 Nov 29 08:08 _97.prx
> -rw-r--r-- 1 user user 187731 Nov 29 08:08 _97.tii
> -rw-r--r-- 1 user user 14617940 Nov 29 08:08 _97.tis
> -rw-r--r-- 1 user user 21310 Nov 29 13:10 _9q_1a.del
> -rw-r--r-- 1 user user 49864395 Nov 29 09:19 _9q.fdt
> -rw-r--r-- 1 user user 1361884 Nov 29 09:19 _9q.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 09:19 _9q.fnm
> -rw-r--r-- 1 user user 17879364 Nov 29 09:19 _9q.frq
> -rw-r--r-- 1 user user 4970178 Nov 29 09:19 _9q.prx
> -rw-r--r-- 1 user user 75969 Nov 29 09:19 _9q.tii
> -rw-r--r-- 1 user user 5932085 Nov 29 09:19 _9q.tis
> -rw-r--r-- 1 user user 62661357 Nov 29 10:19 _a6.fdt
> -rw-r--r-- 1 user user 1717820 Nov 29 10:19 _a6.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 10:19 _a6.fnm
> -rw-r--r-- 1 user user 23283028 Nov 29 10:19 _a6.frq
> -rw-r--r-- 1 user user 6196945 Nov 29 10:19 _a6.prx
> -rw-r--r-- 1 user user 92528 Nov 29 10:19 _a6.tii
> -rw-r--r-- 1 user user 7209783 Nov 29 10:19 _a6.tis
> -rw-r--r-- 1 user user 26871 Nov 29 13:10 _a6_y.del
> -rw-r--r-- 1 user user 16372020 Nov 29 10:39 _ab.fdt
> -rw-r--r-- 1 user user 455476 Nov 29 10:39 _ab.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 10:39 _ab.fnm
> -rw-r--r-- 1 user user 6025966 Nov 29 10:39 _ab.frq
> -rw-r--r-- 1 user user 1622841 Nov 29 10:39 _ab.prx
> -rw-r--r-- 1 user user 35252 Nov 29 10:39 _ab.tii
> -rw-r--r-- 1 user user 2766468 Nov 29 10:39 _ab.tis
> -rw-r--r-- 1 user user 7147 Nov 29 13:10 _ab_u.del
> -rw-r--r-- 1 user user 14818116 Nov 29 11:09 _aj.fdt
> -rw-r--r-- 1 user user 409356 Nov 29 11:09 _aj.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 11:09 _aj.fnm
> -rw-r--r-- 1 user user 5461353 Nov 29 11:09 _aj.frq
> -rw-r--r-- 1 user user 6427 Nov 29 13:10 _aj_o.del
> -rw-r--r-- 1 user user 1458148 Nov 29 11:09 _aj.prx
> -rw-r--r-- 1 user user 33352 Nov 29 11:09 _aj.tii
> -rw-r--r-- 1 user user 2612127 Nov 29 11:09 _aj.tis
> -rw-r--r-- 1 user user 38110008 Nov 29 11:45 _as.fdt
> -rw-r--r-- 1 user user 1050620 Nov 29 11:45 _as.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 11:45 _as.fnm
> -rw-r--r-- 1 user user 14060459 Nov 29 11:45 _as.frq
> -rw-r--r-- 1 user user 16446 Nov 29 13:10 _as_h.del
> -rw-r--r-- 1 user user 3859009 Nov 29 11:45 _as.prx
> -rw-r--r-- 1 user user 64237 Nov 29 11:45 _as.tii
> -rw-r--r-- 1 user user 5017586 Nov 29 11:45 _as.tis
> -rw-r--r-- 1 user user 16700 Nov 29 13:10 _b8_5.del
> -rw-r--r-- 1 user user 39000157 Nov 29 12:45 _b8.fdt
> -rw-r--r-- 1 user user 1066836 Nov 29 12:45 _b8.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 12:45 _b8.fnm
> -rw-r--r-- 1 user user 14714178 Nov 29 12:45 _b8.frq
> -rw-r--r-- 1 user user 3926997 Nov 29 12:45 _b8.prx
> -rw-r--r-- 1 user user 66264 Nov 29 12:45 _b8.tii
> -rw-r--r-- 1 user user 5184642 Nov 29 12:45 _b8.tis
> -rw-r--r-- 1 user user 1253 Nov 29 13:10 _ba_5.del
> -rw-r--r-- 1 user user 2876260 Nov 29 12:55 _ba.fdt
> -rw-r--r-- 1 user user 78236 Nov 29 12:55 _ba.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 12:55 _ba.fnm
> -rw-r--r-- 1 user user 1003401 Nov 29 12:55 _ba.frq
> -rw-r--r-- 1 user user 4 Nov 29 12:55 _ba.nrm
> -rw-r--r-- 1 user user 288722 Nov 29 12:55 _ba.prx
> -rw-r--r-- 1 user user 9570 Nov 29 12:55 _ba.tii
> -rw-r--r-- 1 user user 751621 Nov 29 12:55 _ba.tis
> -rw-r--r-- 1 user user 1268 Nov 29 13:10 _bb_4.del
> -rw-r--r-- 1 user user 2918222 Nov 29 13:00 _bb.fdt
> -rw-r--r-- 1 user user 79196 Nov 29 13:00 _bb.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 13:00 _bb.fnm
> -rw-r--r-- 1 user user 1023436 Nov 29 13:00 _bb.frq
> -rw-r--r-- 1 user user 4 Nov 29 13:00 _bb.nrm
> -rw-r--r-- 1 user user 291484 Nov 29 13:00 _bb.prx
> -rw-r--r-- 1 user user 9786 Nov 29 13:00 _bb.tii
> -rw-r--r-- 1 user user 771678 Nov 29 13:00 _bb.tis
> -rw-r--r-- 1 user user 3946 Nov 29 13:10 _bc_2.del
> -rw-r--r-- 1 user user 9202338 Nov 29 13:00 _bc.fdt
> -rw-r--r-- 1 user user 250604 Nov 29 13:00 _bc.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 13:00 _bc.fnm
> -rw-r--r-- 1 user user 3391169 Nov 29 13:00 _bc.frq
> -rw-r--r-- 1 user user 924341 Nov 29 13:00 _bc.prx
> -rw-r--r-- 1 user user 22168 Nov 29 13:00 _bc.tii
> -rw-r--r-- 1 user user 1740029 Nov 29 13:00 _bc.tis
> -rw-r--r-- 1 user user 1288 Nov 29 13:10 _bd_3.del
> -rw-r--r-- 1 user user 2962866 Nov 29 13:05 _bd.fdt
> -rw-r--r-- 1 user user 80492 Nov 29 13:05 _bd.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 13:05 _bd.fnm
> -rw-r--r-- 1 user user 1038135 Nov 29 13:05 _bd.frq
> -rw-r--r-- 1 user user 4 Nov 29 13:05 _bd.nrm
> -rw-r--r-- 1 user user 287587 Nov 29 13:05 _bd.prx
> -rw-r--r-- 1 user user 10214 Nov 29 13:05 _bd.tii
> -rw-r--r-- 1 user user 802786 Nov 29 13:05 _bd.tis
> -rw-r--r-- 1 user user 1287 Nov 29 13:10 _be_2.del
> -rw-r--r-- 1 user user 2965758 Nov 29 13:10 _be.fdt
> -rw-r--r-- 1 user user 80452 Nov 29 13:10 _be.fdx
> -rw-r--r-- 1 user user 4963 Nov 29 13:10 _be.fnm
> -rw-r--r-- 1 user user 1044808 Nov 29 13:10 _be.frq
> -rw-r--r-- 1 user user 4 Nov 29 13:10 _be.nrm
> -rw-r--r-- 1 user user 292279 Nov 29 13:10 _be.prx
> -rw-r--r-- 1 user user 10155 Nov 29 13:10 _be.tii
> -rw-r--r-- 1 user user 794169 Nov 29 13:10 _be.tis
> -rw-r--r-- 1 user user 3496 Nov 29 13:10 segments_6j
> -rw-r--r-- 1 user user 20 Nov 29 13:09 segments.gen
>
>
> * 2nd question
>
> I tried to use index from 1.4 (load was the same as on index from 3.5)
> but there was problem with synchronization with master (invalid
> javabin format)
> Then I built new index on 3.5 with luceneMatchVersion LUCENE_35
>
>
> * 3d question
>
> Yes. We have some kind of performance test.
>
> reader
> solr 1.4
> reader :
> SolrIndexReader{this=8cca36c,r=ReadOnlyDirectoryReader@8cca36c,refCnt=1,segments=4}
> readerDir :
> org.apache.lucene.store.NIOFSDirectory@/data/solr_data/itemsfull/index
>
> solr 3.5
> reader :
> SolrIndexReader{this=3d01e178,r=ReadOnlyDirectoryReader@3d01e178,refCnt=1,segments=14}
> readerDir :
> org.apache.lucene.store.MMapDirectory@/data/solr_data_350/itemsfull/index
> lockFactory=org.apache.lucene.store.NativeFSLockFactory@294ce5eb
>
> machine: 2x Xeon E5540@2.53GHz, 36GB memory, system Centos 5.6
>
>
> * 4th question
> 3.5 is not maxing at 60rps i think it can process few requests more
> but with 60rps machine utilizes 1200% cpu on 3.5 and 200% on 1.4 (the
> same number of requests)
>
>
>
> * 5th question
>
> I made some test with quiet heavy query (with frange). In both cases
> (1.4 and 3.5) I used the same newSearcher queries and started solr
> without any load.
> Results of debug timing
>
> solr 1.4
>
> <lst name="timing">
> <double name="time">3202.0</double>
> <lst name="prepare">
> <double name="time">8.0</double>
> <lst name="org.apache.solr.handler.component.QueryComponent">
> <double name="time">8.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.FacetComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.MoreLikeThisComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.HighlightComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.StatsComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.DebugComponent">
> <double name="time">0.0</double>
> </lst>
> </lst>
> <lst name="process">
> <double name="time">3193.0</double>
> <lst name="org.apache.solr.handler.component.QueryComponent">
> <double name="time">2988.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.FacetComponent">
> <double name="time">204.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.MoreLikeThisComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.HighlightComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.StatsComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.DebugComponent">
> <double name="time">1.0</double>
> </lst>
> </lst>
> </lst>
>
>
>
> solr 3.5
>
> <lst name="timing">
> <double name="time">4252.0</double>
> <lst name="prepare">
> <double name="time">8.0</double>
> <lst name="org.apache.solr.handler.component.QueryComponent">
> <double name="time">7.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.FacetComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.MoreLikeThisComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.HighlightComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.StatsComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.DebugComponent">
> <double name="time">0.0</double>
> </lst>
> </lst>
> <lst name="process">
> <double name="time">4244.0</double>
> <lst name="org.apache.solr.handler.component.QueryComponent">
> <double name="time">4046.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.FacetComponent">
> <double name="time">197.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.MoreLikeThisComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.HighlightComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.StatsComponent">
> <double name="time">0.0</double>
> </lst>
> <lst name="org.apache.solr.handler.component.DebugComponent">
> <double name="time">1.0</double>
> </lst>
> </lst>
> </lst>
>
>
> When I send fewer than 60 rps I see that in comparsion to 1.4 median
> response time is worse, avarage is worse but maximum time is better.
> It doesn't change propotion of cpu usage (3.5 uses much more cpu).
>
> --
> Pawel
>
> On Wed, Nov 30, 2011 at 12:17 AM, Chris Hostetter
> <hossman_luc...@fucit.org> wrote:
>>
>> : > previous Solr 1.4 index? what does a directory listing (including file
>> : > sizes) look like for both your old and new indexes?
>> :
>> : Yes, both indexes have same data. Indexes are build using some C++
>> : programm which reads data from database and inserts it into Solr
>> : (using XML). Both indexes have about 8GB size and 18milions documents.
>>
>> I'd still like to see the directory listings with filesizes from both
>> indexes. I want to make sure there isn't some wonkiness somewhere in
>> terms of hte number of segments, or huge norms / positions files that you
>> dont' care about because of how some default might have changed w/o us
>> realizing it, etc...
>>
>> : > 2) Did you try using your Solr 1.4 index (and configs) directly in Solr
>> : > 3.5 w/o rebuilding from scratch?
>> :
>> : Yes I used the same configs in solr 1.4 and solr 3.5 (adding only line
>> : about "luceneMatchVersion")
>>
>> that wasn't my question -- i'm understand that when you built your
>> new index you used the same configs as before, i'm asking if you tried
>> pointing Solr 3.5 at the actual physical index you built with Solr 1.4.
>>
>> what did you set luceneMatchVersion to?
>>
>> : Mayby I didn't wrote precisely enough. I have some machine on which
>> : there is master node. I have second machine on which there is slave. I
>> : tested solr 1.4 on that machine, then turned it off and turned on
>> : solr-3.5. I have 36GB RAM on that machine.
>> : On both - solr 1.4 and 3.5 configuration of JVM is the same, and the
>> : same servlet container ... jetty-6
>>
>> So your query performance testing was done running both Solr 1.4 and Solr
>> 3.5 on the same box, but at different times.
>>
>> what type of machine is this? what OS is it running? (There's been some
>> work done on making the default Directory implementations auto-detect when
>> they can use MMap based on OS ... maybe that is guessing poorly in your
>> case? ... what does admin/mbeans?key=searcher&stats=true say about your
>> reader and readerDir ?)
>>
>> : Maybe I wasn't precise enough again. CPU on solr 1.4 was 200% and on
>> : solr 3.5 1200%
>> : yes there is cache warming. There are 50-100 client threads on both
>> : 1.4 and 3.5. There are about 60 requests per second on 3.5 and on 1.4,
>> : but on 3.5 responses are slower and CPU usage much higher.
>>
>> Ah... ok ... so when you say 60 req/sec you don't mean that under
>> continuous load you are measuring that solr 3.5 is maxing out at 60
>> req/sec ... it now sounds like what you are saying is that
>> that you have a load testing system which is configured to use at least 50
>> and at most 100 clients but you also have it configured to try and
>> generate a stead state load of 60 req/sec, and when you do that you are
>> seeing higher CPU and slower QTime on Solr 3.5.
>>
>> ...am i understanding that part correctly?
>>
>> : Most time is in org.apache.solr.handler.component.QueryComponent and
>> : org.apache.solr.handler.component.DebugComponent in process. I didn't
>> : comare individual request performance.
>>
>> Define "most" ? ... if you know that "most" of the time is spent in
>> QueryComponent that suggests that you did at least one or two individual
>> requests directly, how fast were they? was the slow performance you are
>> seeing only under heavy load or was it also slow when you did manual
>> testing?
>>
>>
>> -Hoss
