IRC log for #koha, 2005-04-23

← Previous day | Today | Search | Index

All times shown according to UTC.

Time Nick Message
13:56 kados chris around?
13:58 owen: does this query look familiar to you>
13:58 Select distinct biblio.*, biblioitems.classification from biblio, biblioitems where
13:58 iblio.biblionumber = biblioitems.biblionumber and title like 'something%';
13:58 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 Oh, I see.
13:59 kados yea ... about 30 times in the last couple of hours
14:00 I didn't think any of our searches uses biblio.* anymore
14:01 our circ desk speed issues are strange this time
14:01 load average: 0.39, 0.53, 0.62
14:01 that's really quite low
14:01 (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 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 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 there must be some other tables that need to be reset
14:09 though I don't know what those would be
14:11 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 so maybe it isn't mysql at all
14:12 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 we've had 197,000 queries, about 25 per second and only 15 of those were s
14:19 slow
14:19 that's not too bad
14:19 but it really seems like alot of queries for 1.5 hours eh?
14:21 owen How many queries in an issue?
14:22 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 Queries: 530.0k  qps:   34 Slow:    25.0
17:06 that's after four hours up
17:06 and load is minimal
17:06 chris thats about what id expect
17:06 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 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 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 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 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 maybe about 20 or so
17:10 chris try hitting lynx localhost
17:10 or lynx http://your.koha.site
17:10 come up nice and fast?
17:11 :)
17:11 kados I suppose I could do wget eh?
17:11 or just telnet ;-)
17:11 chris yep
17:11 telnet will see how fast it ansers
17:12 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 if you use lynx you can go thru to circ, and choose a borrower etc
17:13 see how its going
17:14 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 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 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 when was apache last restarted?
17:16 kados actually I double-checked ... it's not on
17:16 it was our test machine that was running it
17:17 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 how fast does a page with no perl on it come up
17:19 do you have a static page you can check with lynx?
17:19 kados not sure ... I'll look
17:23 still abotu 3 seconds
17:23 chris right
17:23 so weve ruled out perl, and mysql
17:23 library is open now?
17:23 kados yea
17:23 2.5 more hours
17:24 chris right
17:24 hmm
17:24 df tell you anything useful?
17:24 no disks full or anything?
17:24 kados nope
17:25 we've got three disks and the most full one is at 25%
17:26 could it be ssl?
17:26 we've got mod_ssl enabled
17:26 chris i dont think so
17:26 cos lynx wont be going to the ssl site
17:26 kados well ... actually
17:26 it was
17:27 chris ahh
17:27 kados I was using the same url
17:27 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 resolve fast?
17:28 kados Query time: 40 msec
17:28 pretty fast
17:28 instant even
17:28 chris there goes that theory then
17:28 kados :-)
17:29 too bad ... I'd love to blame it on DNS
17:29 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 must be cached or something
17:31 chris probably
17:32 weird, i dont know why it would be serving pages so slowly
17:32 reverse dns ok?
17:32 kados I wish there was some way to precisely see exactly what apache was doing
17:32 not sure ... maybe not
17:32 how can I check
17:32 chris take a look at the access log
17:32 grab some ip numbers
17:33 and do host number
17:33 i dont know if openssl does some kinda reverse lookup
17:33 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 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 host number?
17:36 chris yep
17:36 kados host 192.168.1.159
17:36 Host 159.1.168.192.in-addr.arpa not found:
17:36 that's strange ... 192 should be local
17:36 host 192.168.3.51
17:36 Host 51.3.168.192.in-addr.arpa not found
17:37 chris yeah
17:37 kados same thing there
17:37 think that's the problem?
17:37 chris which isnt unexpected
17:37 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 apachectl stop
17:38 apachectl start
17:38 (u only have the one apache running right?)
17:39 kados right
17:39 (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 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 name=reserve_list.php dev=sdb1 ino=131176 scontext=root:system_r:httpd_t tconte
17:45 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 yea
17:46 chris so if its denying httpd .. perl from doing things
17:46 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 and in the other id do some lynx http://66.213.78.77/ etc
17:48 and see if it pops out stuff
17:48 kados would that be /var/log/syslog?
17:48 or /var/log/messages?
17:48 chris syslog probably has it
17:48 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 ksyslog?
17:50 if you cant find it .. just use messages
17:50 kados huh ... no ... but there's a 'dmesg'
17:50 messages didn't turn up anything
17:51 nothing with dmesg either
17:51 bummer
17:51 chris kern.log ?
17:51 kados can't I do something in /proc?
17:52 prelink.log
17:52 acpid
17:52 spooler
17:52 chris what we want is a log thats timestamped
17:52 kados rpmpkgs
17:52 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 selinux doesn't affect root at all
17:53 chris seems bizzare that you dont have a syslog
17:56 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 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 then what?
17:58 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 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 SSL error:unable to get local issuer certificate-Continue? (y)
18:02 its grizzling about that
18:03 everytime
18:03 kados it should be there ...
18:03 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 only in lynx tho
18:04 I just made a new CA yesterday
18:04 and used it to sign our cert
18:04 and I told staff to click "trust indefinitely"
18:05 http://lists.gnu.org/archive/h[…]-12/msg00031.html
18:05 huh .. .may actually be a lynx bug ;-)
18:06 chris :)
18:06 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 time wget https://intranet.athenscounty.lib.oh.us
18:07 real    0m0.973s
18:07 user    0m0.048s
18:07 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 user    0m0.053s
18:08 sys     0m0.005s
18:08 that's on the localhost ;-)
18:08 chris time wget localhost
18:08 real    0m0.017s
18:08 user    0m0.009s
18:08 sys     0m0.007s
18:09 kados real    0m0.017s
18:09 user    0m0.010s
18:09 sys     0m0.006s
18:09 yea
18:09 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 @koha ~]# time wget https://intranet.athenscounty.lib.oh.us
18:10 real    0m0.992s
18:10 user    0m0.049s
18:10 sys     0m0.007s
18:10 is that about what u get?
18:10 kados yep
18:10 chris so that seems ok to me
18:11 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 user    0m0.037s
18:12 sys     0m0.006s
18:12 chris HTTP request sent, awaiting response... 403 Forbidden
18:12 11:11:59 ERROR 403: Forbidden.
18:12 kados right
18:12 chris real    0m2.674s
18:12 user    0m0.036s
18:12 sys     0m0.009s
18:12 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 or two actually
18:13 chris i wonder if somehow we inadvertently sped things up?
18:13 kados hmmm
18:15 nope ... still about 4-6 secs to bring up patron record
18:17 chris hmm seems fast from lynx
18:17 have u tried that?
18:17 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 :-)
18:19 like 1-2 secs?
18:20 I don't get it
18:20 how is that possible?
18:20 chris yeah
18:20 kados weird
18:21 I just did a patron search "Ferraro , Joshua"
18:21 five seconds
18:21 owen, leonard, same deal
18:22 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 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 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 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 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 so that seems fine for nz
18:27 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 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 is that u?
18:28 kados yea
18:28 chris 3 seconds
18:28 seem ok?
18:29 kados well ... I dunno
18:29 it's ok for me ;-)
18:29 chris yeah
18:29 kados staff is complaining that it used to be faster
18:29 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 didnt help much
18:30 :)
23:49 indradg kados, problems with speed?

← Previous day | Today | Search | Index

koha1