orbweb:~$ time wget https://intranet.athenscounty.lib.oh.us← 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/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: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 | chrisorbweb:~$ 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/circulation.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/circulation.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
