Akara hi again, Something weird is going on. Check the following driver.log part from the steady state...
May 4, 2010 10:22:00 PM com.sun.faban.driver.engine.MasterImpl$StatsWriter dumpStats INFO: 115.01s - UIDriver: HomePage/Login/TagSearch/EventDetail/PersonDetail/AddPerson/AddEvent CThru=13.997/3.999/17.397/12.398/1.800/0.400/0.800OThru=12.763/5.141/17.398/12.399/1.388/0.518/0.953 CErr=0.000/0.000/0.000/0.000/0.000/0.000/0.000CResp=0.008/0.008/0.020/0.012/0.075/0.024/0.140 OResp=0.056/0.058/0.076/0.057/0.150/0.035/0.186 CSD=0.000/0.000/0.059/0.000/0.000/0.005/0.000 OSD=0.329/0.302/0.349/0.345/0.307/0.033/0.200 C90%Resp=0.020/0.020/0.040/0.020/0.140/0.020/0.160 O90%Resp=0.020/0.020/0.060/0.040/0.180/0.080/0.160 May 4, 2010 10:22:05 PM com.sun.faban.driver.engine.MasterImpl$StatsWriter dumpStats INFO: 120.01s - UIDriver: HomePage/Login/TagSearch/EventDetail/PersonDetail/AddPerson/AddEvent CThru=12.803/5.401/14.603/12.202/2.200/0.000/1.400OThru=12.765/5.155/17.243/12.388/1.433/0.489/0.978 CErr=0.000/0.000/0.000/0.000/0.000/0.000/0.000CResp=0.008/0.008/0.018/0.010/0.070/-/0.149 OResp=0.053/0.055/0.073/0.055/0.143/0.035/0.184 CSD=0.007/0.000/0.000/0.000/0.000/-/0.000 OSD=0.319/0.293/0.341/0.336/0.292/0.033/0.193 C90%Resp=0.020/0.020/0.040/0.020/0.120/-/0.180 O90%Resp=0.020/0.020/0.060/0.040/0.180/0.080/0.180 May 4, 2010 10:22:10 PM com.sun.faban.driver.engine.MasterImpl$StatsWriter dumpStats INFO: 125.01s - UIDriver: HomePage/Login/TagSearch/EventDetail/PersonDetail/AddPerson/AddEvent CThru=11.400/5.800/18.400/11.800/0.800/0.600/1.000OThru=12.694/5.189/17.304/12.357/1.400/0.495/0.979 CErr=0.000/0.000/0.000/0.000/0.000/0.000/0.000CResp=0.008/0.007/0.018/0.011/0.129/0.031/0.138 OResp=0.051/0.052/0.070/0.052/0.142/0.035/0.181 CSD=0.000/0.019/0.017/0.006/0.000/0.000/0.010 OSD=0.312/0.285/0.332/0.328/0.288/0.032/0.188 C90%Resp=0.020/0.020/0.040/0.020/0.180/0.040/0.160 O90%Resp=0.020/0.020/0.060/0.040/0.180/0.080/0.180 May 4, 2010 10:22:19 PM com.sun.faban.driver.engine.MasterImpl$StatsWriter dumpStats INFO: 133.57s - UIDriver: HomePage/Login/TagSearch/EventDetail/PersonDetail/AddPerson/AddEvent CThru=9.116/4.324/12.973/9.233/0.468/0.117/0.468OThru=12.398/5.118/16.946/12.099/1.323/0.463/0.937 CErr=0.000/0.000/0.000/0.000/0.000/0.000/0.000 CResp=0.021/0.007/0.033/0.075/0.094/0.033/0.177 OResp=0.049/0.049/0.068/0.054/0.141/0.035/0.181 CSD=0.115/2.938/0.108/0.372/0.000/0.000/0.380 OSD=0.304/0.276/0.322/0.331/0.284/0.031/0.199 C90%Resp=0.020/0.020/0.060/0.040/0.120/0.020/0.220 O90%Resp=0.020/0.020/0.060/0.040/0.180/0.080/0.180 May 4, 2010 10:22:20 PM com.sun.faban.driver.engine.MasterImpl$StatsWriter dumpStats INFO: 135.01s - UIDriver: HomePage/Login/TagSearch/EventDetail/PersonDetail/AddPerson/AddEvent CThru=3.463/1.385/4.155/4.155/0.000/0.000/0.000OThru=12.275/5.066/16.770/11.989/1.305/0.457/0.924 CErr=0.000/0.000/0.000/0.000/0.000/0.000/0.000CResp=0.775/0.170/0.131/1.253/-/-/- OResp=0.052/0.050/0.068/0.059/0.141/0.035/0.181 CSD=1.237/0.078/13.954/0.935/-/-/- OSD=0.316/0.276/0.321/0.346/0.284/0.031/0.199 C90%Resp=0.320/0.160/0.180/1.700/-/-/- O90%Resp=0.020/0.020/0.060/0.040/0.180/0.080/0.180 May 4, 2010 10:22:25 PM com.sun.faban.driver.engine.MasterImpl$StatsWriter dumpStats INFO: 140.01s - UIDriver: HomePage/Login/TagSearch/EventDetail/PersonDetail/AddPerson/AddEvent CThru=0.000/0.000/0.000/0.000/0.200/0.000/0.000OThru=11.717/4.836/16.008/11.444/1.254/0.436/0.882 CErr=0.000/0.000/0.000/0.000/0.000/0.000/0.000 CResp=-/-/-/-/1.751/-/- OResp=0.052/0.050/0.068/0.059/0.153/0.035/0.181 CSD=-/-/-/-/0.000/-/- OSD=0.316/0.276/0.321/0.346/0.315/0.031/0.199 C90%Resp=-/-/-/-/0.020/-/- O90%Resp=0.020/0.020/0.060/0.040/0.180/0.080/0.180 May 4, 2010 10:22:30 PM com.sun.faban.driver.engine.MasterImpl$StatsWriter dumpStats INFO: 145.01s - UIDriver: HomePage/Login/TagSearch/EventDetail/PersonDetail/AddPerson/AddEvent CThru=0.000/0.000/0.000/0.000/0.000/0.000/0.000OThru=11.208/4.626/15.312/10.947/1.200/0.417/0.843 CErr=0.000/0.000/0.000/0.000/0.000/0.000/0.000 CResp=-/-/-/-/-/-/- OResp=0.052/0.050/0.068/0.059/0.153/0.035/0.181 CSD=-/-/-/-/-/-/- OSD=0.316/0.276/0.321/0.346/0.315/0.031/0.199 C90%Resp=-/-/-/-/-/-/- O90%Resp=0.020/0.020/0.060/0.040/0.180/0.080/0.180 May 4, 2010 10:22:35 PM com.sun.faban.driver.engine.MasterImpl$StatsWriter dumpStats INFO: 150.01s - UIDriver: HomePage/Login/TagSearch/EventDetail/PersonDetail/AddPerson/AddEvent CThru=0.000/0.000/0.000/0.000/0.000/0.000/0.000OThru=10.741/4.433/14.674/10.491/1.150/0.400/0.808 CErr=0.000/0.000/0.000/0.000/0.000/0.000/0.000 CResp=-/-/-/-/-/-/- OResp=0.052/0.050/0.068/0.059/0.153/0.035/0.181 CSD=-/-/-/-/-/-/- OSD=0.316/0.276/0.321/0.346/0.315/0.031/0.199 C90%Resp=-/-/-/-/-/-/- O90%Resp=0.020/0.020/0.060/0.040/0.180/0.080/0.180 May 4, 2010 10:22:40 PM com.sun.faban.driver.engine.MasterImpl$StatsWriter dumpStats INFO: 155.01s - UIDriver: HomePage/Login/TagSearch/EventDetail/PersonDetail/AddPerson/AddEvent CThru=0.000/0.000/0.000/0.000/0.000/0.000/0.000OThru=10.311/4.256/14.087/10.071/1.104/0.384/0.776 CErr=0.000/0.000/0.000/0.000/0.000/0.000/0.000 CResp=-/-/-/-/-/-/- OResp=0.052/0.050/0.068/0.059/0.153/0.035/0.181 CSD=-/-/-/-/-/-/- OSD=0.316/0.276/0.321/0.346/0.315/0.031/0.199 C90%Resp=-/-/-/-/-/-/- O90%Resp=0.020/0.020/0.060/0.040/0.180/0.080/0.180 May 4, 2010 10:22:45 PM com.sun.faban.driver.engine.MasterImpl$StatsWriter dumpStats I have highlighted the interesting parts. The execution proceeds nornally till a certain point, when (I have verified with vmstat) it starts swapping (there is not enough memory in the virtual machine). At this point cpu goes to 100% and CThru is stack at 0 after that and no CErr are reported. Any intuition on CErr is stuck at 0 as well? Is there any way to detect this situation, besides looking at the throughput numbers? The expected behavior would be to log a huge amount of CErr, all the operations basically during the interval. Right? Thanks ------------------------------------------------------------------- Kontorinis Vasileios Phd student, University of California San Diego San Diego, CA 92122 Cell. phone: (858) 717 6899 [email protected], [email protected] ------------------------------------------------------------------- 2010/5/5 Akara Sucharitakul <[email protected]> > Hmmm, the apache mailing list won't let my current email post a reply. > Trying again. > > -Akara > > -------- Original Message -------- Subject: Re: Parsing Olio runtimeStats > Date: > Wed, 05 May 2010 14:17:35 -0700 From: Akara Sucharitakul > <[email protected]> <[email protected]> Reply-To: > [email protected] Organization: Oracle To: > [email protected] CC: akara.sucharitakul > <[email protected]> <[email protected]>, Shanti > Subramanyam <[email protected]> <[email protected]> > References: > <[email protected]><[email protected]> > > Let me try to address this below: > > > On 05/05/10 12:12, Vasileios Kontorinis wrote: > > Akara and Shanti hi, > I am parsing the runtimeStats from the driver.log file and I run into > this interesting issue. > In the output for *steady state* I get "-" for the response time when > there are no successful operations since the last time runtimeStats were > printed. > This can happen for two reasons: > 1) The interval for printing the runtimeStats is small (in my case 5secs) > and some operations, especially the ones that take long and have small > frequency in matrix (add event, add user) just never happened. > > Yes, if the number of successful operations in that period is 0, most > calculations will be a divide by 0. That's why it is printing a '-'. > > 2) There are a bunch of requests going on and none of them is successful. > This can happen when there is no sufficient memory in the machine. In that > case there is lots of swapping, the cpu goes to 100% utilization and all the > operations time-out. > > Is there any small change I can do to distinguish between the two cases? > Maybe printing a small "t" when there are many requests timing out, so that > I can distinguish between the two cases? Any ideas are welcome. > > There is the error count in the runtime stats that tell you about error > cases. This would also include timeouts. But the problem is not that simple. > The real problem is not the operations timing out but rather the operations > waiting that would time out. And we cannot distinguish between these > waiting operations and other operations waiting just with slow response > time. > > > One more thing. I use the variableLoad setting and in order to know how > many users are simulated while the benchmark run, I parse log.xml looking > for "Active threads: ". The problem is that log.xml is big especially when > many requests timeout. Is it easy to also log the changes of active threads > in the drive.log file ?? > > > Please look into log configuration in $FABAN/config/logging.properties. You > should be able to make certain loggers log to a particular file. I don't > have the detail off the top of my head. > > -Akara > >
