IRC log for #koha, 2005-04-23

All times shown according to UTC.

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

| Channels | #koha index | Today | Search | Google Search | Plain-Text | plain, newest first | summary