Time Nick Message
23:49 indradg kados, problems with speed?
18:30 chris :)
18:30 chris didnt help much
18:29 chris no problem
18:29 kados thanks for the help
18:29 chris will do
18:29 kados if you think of anything let me know
18:29 chris yep
18:29 kados oh well ... I know you prolly have to get back to work
18:29 kados staff is complaining that it used to be faster
18:29 chris yeah
18:29 kados it's ok for me ;-)
18:29 kados well ... I dunno
18:28 chris seem ok?
18:28 chris 3 seconds
18:28 kados yea
18:28 chris is that u?
18:28 chris 70.105.97.223 - - [21/Apr/2005:19:27:43 -0400] "GET /cgi-bin/koha/circ/circulation.pl?findborrower=0006067 HTTP/1.1" 200 21091
18:28 chris 70.105.97.223 - - [21/Apr/2005:19:27:40 -0400] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 200 8427
18:27 kados OK ... I just tried
18:27 chris its really hard to test speed actually
18:26 chris so that seems fine for nz
18:26 chris and send the data
18:26 kados right
18:26 chris 4 seconds to find it, 5 to pull up the record and send it back .. that includes how long it too ke to click etc
18:25 kados how does that compare to hlt?
18:25 chris 202.0.55.84 - - [21/Apr/2005:19:25:10 -0400] "GET /cgi-bin/koha/circ/circulation.pl?findborrower=0006067 HTTP/1.1" 200 21091
18:25 chris 202.0.55.84 - - [21/Apr/2005:19:25:05 -0400] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 200 8427
18:25 chris 202.0.55.84 - - [21/Apr/2005:19:25:01 -0400] "GET /cgi-bin/koha/mainpage.pl HTTP/1.1" 200 9963
18:25 kados neat idea
18:24 kados ahh
18:24 chris im using the apache logs to see when apache returns the page
18:24 kados I'm counting from when I hit submit till it comes up
18:23 chris 4 seconds to do a search on owen leonard, that includes the time it took me to paste in owen,leonard and hit submit
18:23 kados is the last column the time?
18:22 chris 202.0.55.84 - - [21/Apr/2005:19:22:28 -0400] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 200 8427
18:22 chris 202.0.55.84 - - [21/Apr/2005:19:22:24 -0400] "GET /cgi-bin/koha/mainpage.pl HTTP/1.1" 200 9963
18:22 kados 8 seconds to bring up owen's 'issue' screen
18:21 kados owen, leonard, same deal
18:21 kados five seconds
18:21 kados I just did a patron search "Ferraro , Joshua"
18:20 kados weird
18:20 chris yeah
18:20 kados how is that possible?
18:20 kados I don't get it
18:19 kados like 1-2 secs?
18:19 kados :-)
18:19 kados bullshit!
18:19 chris from my browser here the page comes up in a nice fast time
18:19 kados when you say 'fast in lynx' ... what do you mean?
18:19 chris weird that seems fine
18:17 kados hehe
18:17 chris tsk tsk tsk 14 overdues
18:17 chris have u tried that?
18:17 chris hmm seems fast from lynx
18:15 kados nope ... still about 4-6 secs to bring up patron record
18:13 kados hmmm
18:13 chris i wonder if somehow we inadvertently sped things up?
18:13 kados or two actually
18:12 kados so ... we've also only got one branch going atm
18:12 chris so it appears apache seems fine
18:12 kados it's right
18:12 chris which isnt bad from nz
18:12 chris sys 0m0.009s
18:12 chris user 0m0.036s
18:12 chris real 0m2.674s
18:12 kados right
18:12 chris 11:11:59 ERROR 403: Forbidden.
18:12 chris HTTP request sent, awaiting response... 403 Forbidden
18:12 kados sys 0m0.006s
18:12 kados user 0m0.037s
18:12 kados real 0m0.905s
18:12 chris chris@orbweb:~$ time wget https://intranet.athenscounty.lib.oh.us
18:12 kados that particular command is pretty fast even from my home server
18:11 chris is it still slow from off the machine?
18:10 chris so that seems ok to me
18:10 kados yep
18:10 chris is that about what u get?
18:10 chris sys 0m0.007s
18:10 chris user 0m0.049s
18:10 chris real 0m0.992s
18:10 chris @koha ~]# time wget https://intranet.athenscounty.lib.oh.us
18:09 chris so it should be the same
18:09 kados ahh
18:09 chris im doing it on the machine
18:09 kados so your connection to our DNS is faster than ours ;-)
18:09 kados yea
18:09 kados sys 0m0.006s
18:09 kados user 0m0.010s
18:09 kados real 0m0.017s
18:08 chris sys 0m0.007s
18:08 chris user 0m0.009s
18:08 chris real 0m0.017s
18:08 chris time wget localhost
18:08 kados that's on the localhost ;-)
18:08 kados sys 0m0.005s
18:08 kados user 0m0.053s
18:08 kados real 0m1.127s
18:07 chris that of course is just getting me the login page
18:07 kados wow ... that's really fast
18:07 chris sys 0m0.011s
18:07 chris user 0m0.048s
18:07 chris real 0m0.973s
18:07 chris time wget https://intranet.athenscounty.lib.oh.us
18:06 chris nope page seems to come up pretty fast
18:06 kados really?
18:06 chris well it doesnt feel too slow from lynx
18:06 chris :)
18:05 kados huh .. .may actually be a lynx bug ;-)
18:05 kados http://lists.gnu.org/archive/html/lynx-dev/2002-12/msg00031.html
18:04 kados and I told staff to click "trust indefinitely"
18:04 kados and used it to sign our cert
18:04 kados I just made a new CA yesterday
18:03 kados only in lynx tho
18:03 kados yep
18:03 chris does it do it to you
18:03 kados maybe that's it
18:03 chris that might be the problem
18:03 kados huh ...
18:03 kados it should be there ...
18:03 chris everytime
18:02 chris its grizzling about that
18:02 chris SSL error:unable to get local issuer certificate-Continue? (y)
18:02 chris hmm and the intranet came up pretty fast as well
18:01 kados right ... searching is actually quite fast
18:01 chris well the opac doesnt seem unduly slow
18:01 kados unless syslogd now breaks everything up into seperate files
18:01 chris ud think so :)
18:00 kados btw since there's a syslogd there myst be a syslog ;-)
18:00 chris yeah
17:59 kados right ... well since my key buffer is like a gig that's probably why it's so high
17:59 chris VIRT stands for the virtual size of a process, which is the sum of memory it is actually using, memory it has mapped into itself (for instance the video card's RAM for the X server), files on disk that have been mapped into it (most notably shared libraries), and memory shared with other processes. VIRT represents how much memory the program is able to access at the present moment.
17:58 chris but i dont think thats our problem
17:58 kados what does it mean?
17:58 chris yep .. thats pretty big
17:58 kados 1158m
17:57 kados then what?
17:57 kados ok
17:57 chris do a top
17:57 kados VIRT?
17:57 chris look at the VIRT on mysql
17:57 kados what's up?
17:57 kados the last one is at 1:00 eh?
17:57 chris eep
17:56 kados right
17:56 chris try grep "httpd" /var/log/messages
17:53 chris seems bizzare that you dont have a syslog
17:53 kados selinux doesn't affect root at all
17:52 kados I don't think so
17:52 chris maybe selinux hides them all
17:52 kados hehe
17:52 chris i wonder where the hell ur logs are
17:52 kados right
17:52 kados rpmpkgs
17:52 chris what we want is a log thats timestamped
17:52 kados spooler
17:52 kados acpid
17:52 kados prelink.log
17:51 kados can't I do something in /proc?
17:51 chris kern.log ?
17:51 kados bummer
17:51 kados nothing with dmesg either
17:50 kados messages didn't turn up anything
17:50 kados huh ... no ... but there's a 'dmesg'
17:50 chris if you cant find it .. just use messages
17:49 chris ksyslog?
17:49 chris hmm anything like syslog?
17:48 kados hmmm ... I don't see a syslog
17:48 chris and it has dates/times too
17:48 chris syslog probably has it
17:48 kados or /var/log/messages?
17:48 kados would that be /var/log/syslog?
17:48 chris and see if it pops out stuff
17:47 chris and in the other id do some lynx http://66.213.78.77/ etc
17:47 chris in one id run tail -f /var/log/syslog
17:47 kados yep
17:47 chris have u got 2 screens open on that machine?
17:47 kados hmmm, well selinux is off ...
17:46 chris thats gotta slow stuff down ud imagine
17:46 chris so if its denying httpd .. perl from doing things
17:46 kados yea
17:46 kados audit(1114103202.963:0): avc: denied { ioctl } for pid=15230 exe=/usr/bin/perl path=/build/cvsroots/production/koha/search.marc/search.pl dev=sdb1 ino=150125 scontext=root:system_r:httpd_t tcontext=root:object_r:root_t tclass=file
17:45 chris that looks suspicious eh
17:45 kados looks like selinux stuff ... but I think selinux is off
17:45 chris hmmm
17:45 kados xt=root:object_r:root_t tclass=lnk_file
17:45 kados name=reserve_list.php dev=sdb1 ino=131176 scontext=root:system_r:httpd_t tconte
17:45 kados audit(1110890843.402:0): avc: denied { read } for pid=353 exe=/usr/sbin/httpd
17:41 chris well i have no idea whats going on
17:41 kados still about 4 secs for the mainpage on lynx on the localhost
17:40 kados ok
17:39 chris :)
17:39 kados yep ;-)
17:39 chris it wont annoy the librarians?
17:39 kados I can do that now
17:39 chris stop .. wait 5 seconds or so, start
17:39 kados (well ... I think so)
17:39 kados right
17:38 chris (u only have the one apache running right?)
17:38 chris apachectl start
17:38 chris apachectl stop
17:38 chris i think when the library closes id try a
17:37 kados right
17:37 chris i dont know .. i dont know why it would just start being a problem
17:37 chris which isnt unexpected
17:37 kados think that's the problem?
17:37 kados same thing there
17:37 chris yeah
17:36 kados Host 51.3.168.192.in-addr.arpa not found
17:36 kados host 192.168.3.51
17:36 kados that's strange ... 192 should be local
17:36 kados Host 159.1.168.192.in-addr.arpa not found:
17:36 kados host 192.168.1.159
17:36 chris yep
17:36 kados host number?
17:36 kados so what do I do with the IPs?
17:35 chris sweet
17:35 kados Koha's is all IPs
17:35 chris koha
17:35 kados is this the koha acces log or the httpd access log?
17:34 chris heres a bit of mine
17:34 kados I'm not sure how to read this ...
17:34 chris there shouldnt be any host names :)
17:34 chris if apache does dns lookups
17:34 kados hmmm I guess there are a few ...
17:34 chris cripes thats gotta be slowing stuff down
17:34 kados just dnses
17:34 chris ohhh, its resolving them all???
17:33 kados I don't see any IPs in access log
17:33 chris i know ssh does
17:33 chris i dont know if openssl does some kinda reverse lookup
17:33 chris and do host number
17:32 chris grab some ip numbers
17:32 chris take a look at the access log
17:32 kados how can I check
17:32 kados not sure ... maybe not
17:32 kados I wish there was some way to precisely see exactly what apache was doing
17:32 chris reverse dns ok?
17:32 chris weird, i dont know why it would be serving pages so slowly
17:31 chris probably
17:31 kados must be cached or something
17:31 kados naw ... I tried https again and its 23 now
17:31 chris right vs https:// ?
17:31 kados 23 msec
17:30 chris is http://intranet.athenscounty.lib.oh.us any faster?
17:29 kados then I'd have an excuse to get stephen to buy me some DNS servers ;-)
17:29 kados too bad ... I'd love to blame it on DNS
17:28 kados :-)
17:28 chris there goes that theory then
17:28 kados instant even
17:28 kados pretty fast
17:28 kados Query time: 40 msec
17:28 chris resolve fast?
17:27 chris dig intranet.athenscounty.lib.oh.us
17:27 kados yea?
17:27 chris ohh i have an idea
17:27 kados https://intranet.athenscounty.lib.oh.us
17:27 kados I was using the same url
17:27 chris ahh
17:26 kados it was
17:26 kados well ... actually
17:26 chris cos lynx wont be going to the ssl site
17:26 chris i dont think so
17:26 kados we've got mod_ssl enabled
17:26 kados could it be ssl?
17:25 kados we've got three disks and the most full one is at 25%
17:24 kados nope
17:24 chris no disks full or anything?
17:24 chris df tell you anything useful?
17:24 chris hmm
17:24 chris right
17:23 kados 2.5 more hours
17:23 kados yea
17:23 chris library is open now?
17:23 chris so weve ruled out perl, and mysql
17:23 chris right
17:23 kados still abotu 3 seconds
17:19 kados not sure ... I'll look
17:19 chris do you have a static page you can check with lynx?
17:19 chris how fast does a page with no perl on it come up
17:19 chris hmmm
17:19 kados yep
17:19 chris after the apache restart?
17:18 kados still about 4 secs for a patron accout on the localhost using lynx
17:18 chris id try an apachectl restart
17:17 kados shoot ... even that's turned off
17:17 chris could be
17:17 kados could it be Apache::DBI?
17:16 kados it was our test machine that was running it
17:16 kados actually I double-checked ... it's not on
17:16 chris when was apache last restarted?
17:16 chris and i suspect mod_perl/apache misbehaving
17:16 kados four secs to bring up a patron account
17:15 chris so there is something dicey going on
17:15 chris right
17:15 kados even on the localhost it's two secs to bring up mainpage
17:14 chris its slow on the LAN too?
17:14 chris and if that all feels fine ... might be worth checking with the circ ppl how long their computer has been up ... and how long firefox or ie has been running .. it could perhaps be their browser rendering slow
17:13 chris see how its going
17:13 chris if you use lynx you can go thru to circ, and choose a borrower etc
17:12 chris it could be perl or apache being slow
17:12 kados ok it's answering pretty fast
17:12 chris wget or lynx will give you a better idea how long it takes to serve a page
17:11 chris telnet will see how fast it ansers
17:11 chris yep
17:11 kados or just telnet ;-)
17:11 kados I suppose I could do wget eh?
17:11 chris :)
17:10 chris come up nice and fast?
17:10 chris or lynx http://your.koha.site
17:10 chris try hitting lynx localhost
17:10 kados maybe about 20 or so
17:09 kados well there are a log of httpd's listed
17:09 chris and apache isnt huge?
17:09 kados Mem: 2076232k total, 1503312k used, 572920k free, 241376k buffers
17:09 chris thats good then
17:09 kados a 2 goes before that ;-)
17:09 kados 048276k total, 212k used
17:08 chris much swap in use?
17:08 kados when I sort by 'm'
17:08 chris what does top tell ya
17:08 chris it doesnt feel like mysql
17:08 kados so it might not be mysql
17:08 chris yep
17:07 kados and all of the slow queries have been isbn searches
17:07 chris yeah the queries for issues/returns are all really simple
17:07 kados my logslowqueries variable in mysql is set to 1 sec
17:07 kados yep
17:07 chris 5-7 seconds is a really long time
17:06 kados could be ... I've not really done much with apache tuning ... not sure where to begin
17:06 kados well under 1 most of the day with a few peaks at about 3 or so (probably when one of our scripts was running)
17:06 chris is apache serving pages slowly?
17:06 chris thats about what id expect
17:06 kados and load is minimal
17:06 kados that's after four hours up
17:05 kados Queries: 530.0k qps: 34 Slow: 25.0
17:05 kados mytop has:
14:22 owen It certainly could add up fast.
14:22 kados no idea ... probably quite a few
14:22 owen How many in a return?
14:21 owen How many queries in an issue?
14:19 kados but it really seems like alot of queries for 1.5 hours eh?
14:19 kados that's not too bad
14:19 kados slow
14:19 kados we've had 197,000 queries, about 25 per second and only 15 of those were s
14:18 kados Queries: 197.7k qps: 35 Slow: 15.0
14:15 owen It was probably just me waving my mouse threateningly over the search button.
14:12 kados wow ... now load's jumped way up to almost 4.0
14:11 kados so maybe it isn't mysql at all
14:11 kados I've got the slow query log to log all queries taking longer that one second ... and the only ones showing up are those isbnsearch ones
14:09 kados though I don't know what those would be
14:09 kados there must be some other tables that need to be reset
14:08 kados right ... 100Mb
14:08 owen And for them it can't be the network, because they're all right there in the building, right?
14:07 kados but reports from APL say things are still taking 3-6 secs per transaction
14:05 kados I thought for sure it was the issues table
14:05 owen I'm not sure if the change was in isbnsearch.pl and Search.pm, or just isbnsearch.pl
14:05 kados well still, that's not really what's causing the slow down
14:04 kados yea ... I cant find it using grep
14:03 owen Only I think isbnsearch() isn't used anymore (in the release just following our installation)
14:03 kados hmmm ... yea that looks like it
14:01 owen check out Search.pm, line 2465: sub isbnsearch
14:01 kados (when things were bad it was often over 100)
14:01 kados that's really quite low
14:01 kados load average: 0.39, 0.53, 0.62
14:01 kados our circ desk speed issues are strange this time
14:00 kados I didn't think any of our searches uses biblio.* anymore
13:59 kados yea ... about 30 times in the last couple of hours
13:59 owen Oh, I see.
13:59 owen Repeatedly?
13:59 kados no ... I added that ;-)
13:59 owen Uh...I don't know. It has my usual test string 'something'.
13:58 kados it keeps showing up in the slow query log
13:58 kados iblio.biblionumber = biblioitems.biblionumber and title like 'something%';
13:58 kados Select distinct biblio.*, biblioitems.classification from biblio, biblioitems where
13:58 kados owen: does this query look familiar to you>
13:56 kados chris around?