IRC log for #koha, 2005-04-28

All times shown according to UTC.

Time S Nick Message
16:12 kados "600a", # SUBJECT ADDED ENTRY--PERSONAL NAME
16:12 kados "610a", # SUBJECT ADDED ENTRY--CORPORATE NAME
16:12 kados "611a", # SUBJECT ADDED ENTRY--MEETING NAME
16:12 kados "630a", # SUBJECT ADDED ENTRY--UNIFORM TITLE
16:12 kados "650a", # SUBJECT ADDED ENTRY--TOPICAL TERM
16:12 kados "651a", # SUBJECT ADDED ENTRY--GEOGRAPHIC NAME
16:38 kados let's bring owen into this
16:38 chris owen: how much flash do you know?
16:38 chris :)
16:39 owen Uh... not much at all.  But I have a copy :)  I just never get around to learning it.
16:39 chris in my quest for faster solutions, I know that the ppl up in michigan had a go with flash
16:39 kados owen: could our circ speed probs be related to browsers not caching stuff?
16:39 chris we should ask stephen about it, i think he saw it in action
16:39 kados yea it was pretty nifty
16:39 kados I saw it too
16:40 kados i actually emailed them about it a while ago
16:40 chris cool, i wonder if we bug them they would give us a copy?
16:40 kados when were having major speed problems (last time we were having major speed problems ;-))
16:40 owen Could be...I know browsers don't cache some things when you're working over SSL.  I don't know if style sheets are included in that or not.
16:40 chris hmmm
16:41 kados hmm, well I turned off ssl for a bit to see if things improved and staff didn't say much about it ...
16:41 kados maybe I should try turning it off for a whole day and mention it in our staff forum and see if anyone responds
16:41 owen How long was it off?  Just on Saturday?
16:41 kados yea
16:42 kados maybe for a few hours
16:42 kados issues table is now 1/3 it's original size
16:42 kados so I don't this it's that
16:42 kados the reserves table is pretty big though
16:42 kados maybe that's slowing things up?
16:43 owen Yeah, I'm still getting calls about that issues table trim.
16:43 kados select count(*) from reserves;
16:43 kados 22682
16:43 kados hehe
16:43 kados sorry about that
16:43 chris i dont think that would be it
16:44 chris thats pretty small in the scheme of things
16:44 kados select count(*) from statistics;
16:44 kados 2300680
16:44 kados but writes are fast right?
16:44 chris yep
16:44 kados so taht shouldn't matter
16:44 chris as i said, i dont think its mysql
16:45 kados right ... although ... if you saw my message last Sun (your Mon) ...
16:45 chris ill get the tk issues to a point thats usable, then ill give you a copy to try on ur test machine
16:45 kados I restarted the machine after upgrading the kernel and removed selinux
16:46 chris right
16:46 kados and suddenly all kinds of stuff started showing up in the slow_query log
16:46 kados i don't know if that's because of the reboot ...
16:46 chris is it still showing up?
16:46 kados yep
16:46 kados pretty much every query
16:46 kados related to searching
16:47 chris did you try bringing it back up in the old kernel?
16:47 kados yep
16:47 kados no change
16:47 kados I even tried running 'repair table' on marc_word
16:47 kados and did a complete myisamchk on the Koha datbase
16:48 chris right
16:48 kados i was certain that before this none of the marc_word queries were taking more than a second
16:48 kados now they're 5-6 seconds
16:48 kados just in mysql
16:48 chris something must have changed in the reboot then
16:49 kados load is still pretty low though
16:49 kados load average: 1.98, 1.12, 0.96
16:49 kados average is usually under 1
16:49 kados (this is a busy time of the day)
16:49 chris right
16:50 chris im afraid i have no idea what its doing
16:50 kados early this morning I was using top to time 'circulation.pl'
16:50 kados when no searchings were going through
16:51 kados it was taking 2-3 secs
16:51 kados that's with top configured to reset every .1 secs
16:51 chris yep, thats not a real test tho
16:51 chris since top loads the machine up
16:51 kados I know ;-)
16:51 chris and its also being run thru the webserver
16:51 chris so its waiting on lots of other things
16:52 kados true ... but when I did 'P' to sort by CPU time circulation.pl stays t top for 2-3 secs
16:52 kados it seems like there was a time when I could barely see it fly by in top
16:52 chris what we need to do to test it is run it from the commandline
16:53 kados yea?
16:53 kados how do I pass the cgi?
16:53 chris there is some way you can pass parameters in
16:54 chris i cant recall, ill go read
16:55 owen I'll bet the Flash solution works much in the same way an XMLHttpRequest solution would.
16:56 kados http://www.experts-exchange.co[…]l/Q_10259294.html
16:56 kados I'm not signed up there ... chris are you?
16:56 chris your_script.pl name1=value1 name2=value2
16:56 chris i used to be a long time ago
16:57 kados so ...
16:57 kados ./circulation.pl findborrower-0054313
16:57 chris wed have to disable the auth check
16:57 chris cos it wont be able to fetch the cookie
16:57 chris authnotrequired => 0,
16:58 kados right ... better make a copy of the script
16:58 chris ill change that to 1 and try a test here
16:59 kados wow ... it actually took a couple seconds
16:59 chris time perl -I /usr/local/koha/intranet/modules circulation.pl findborrower=v1
16:59 chris real    0m0.650s
16:59 chris but my machine isnt doing a lot
17:00 kados real    0m1.424suser    0m0.851ssys     0m0.045s
17:00 chris now ull notice .. it pauses a bit at the start
17:00 kados right
17:00 chris whatever its doing there is the slow bit
17:00 kados makes sense
17:01 kados can we do strace on it?
17:01 chris we can do the perl equivalent
17:01 chris lemme look it up
17:04 owen See y'all tomorrow
17:04 kados by owen
17:07 chris The granddaddy of Perl profiling tools is Devel::DProf. To profile a code run, add the -d:DProf argument to your Perl command line and let it go:
17:08 chris    % perl -d:DProf store_archive
17:08 kados sweet
17:09 kados so ... store_archive would be the output?
17:09 chris no, that the name of the program
17:09 kados ahh
17:09 chris u end up with a file tmon.out
17:10 kados k
17:10 chris now we need to use dprofpp
17:11 kados time perl -d:DProf -I /build/koha circulation.pl findborrower=0054243 > tmon.out
17:11 chris u dont need the >
17:11 kados I dont' think that worked
17:11 kados ahh
17:11 chris and drop the time as well :)
17:12 chris that work?
17:13 kados I think so
17:13 chris if you do an ls there should be a file called tmon.out there now
17:13 kados yea ... got it
17:13 chris then run dprofpp
17:13 chris and ull see something like that
17:13 chris this
17:13 kados http://kados.org/tmon.out
17:13 chris Total Elapsed Time = 0.762654 Seconds
17:13 chris  User+System Time = 0.492654 Seconds
17:13 chris Exclusive Times
17:13 chris %Time ExclSec CumulS #Calls sec/call Csec/c  Name
17:13 chris 22.3   0.110  0.130      4   0.0275 0.0324  C4::Date::BEGIN
17:14 chris the tmon.out file wont tell us anything until we run
17:14 chris dbprofpp
17:14 chris so dprofpp
17:14 kados command not found
17:14 chris hmm
17:14 kados ahh ... I mispelled
17:14 chris dprofpp
17:14 chris it is
17:14 chris i keep wanting to put a b in it :)
17:15 kados http://kados.org/dprof.txt
17:15 chris right
17:15 chris C4::Date took 28% of the time
17:16 kados interesting
17:16 chris and for me 22%
17:16 chris so that looks to be the culprit
17:16 kados so that's a problem ;-)
17:16 kados we don't care that much about the time ;-
17:16 kados wow ... this is really cool
17:16 kados I can do this will all the scripts
17:17 kados thanks for showing me
17:17 chris no problem
17:17 chris i reckon its date::manip
17:18 chris Total Elapsed Time = 0.857364 Seconds
17:18 chris  User+System Time = 0.837364 Seconds
17:18 chris thats not too bad tho
17:18 chris but perhaps looking for a lightweight/faster replacement for date::manip is the way to go
17:19 kados we'd only need to change it in Date.pm right?
17:19 chris yep
17:19 kados can't perl do dates natively?
17:19 chris yeah if we rewrote Date.pm to not use Date::Manip
17:19 chris we'd probably win a big speed increase
17:21 kados I recon I could do that as long as nothing fishy's going on
17:21 kados using localtime(time)
17:21 chris hmm
17:21 kados here's a snip from some code I've already written:
17:21 kados my ($sec,$min,$hour,$mday,$mon​,$year,$wday,$yday,$isdst)
17:21 kados                                            = localtime(time);
17:21 kados $year +=1900;
17:21 kados $mon +=1; if ($mon < 10) {$mon = "0".$mon;}
17:21 chris have u looked at Date.pm .. its just for converting dates to and from their display format
17:22 kados if ($mday < 10) {$mday = "0".$mday;}
17:22 chris yep that works for today
17:22 chris but
17:22 chris format_date takes a date (presumably one just fetched from mysql)
17:23 chris and formats it as mm/dd/yy or yy/mm/dd or dd/mm/yy
17:23 chris depending on the preference
17:23 kados ahh ... well that's simple substitution
17:23 chris so that would be easy to do without date::manip
17:23 chris as long as the dates are coming from mysql
17:23 chris cos they will always be in the format yyyy-mm-dd
17:23 chris so u can just split that, and rebuild it easy
17:24 kados right
17:24 chris ive gotta go into town for a conference thing now
17:24 kados I'll work on that after dinner
17:24 kados k
17:24 kados thanks chris!
17:24 chris good luck
17:24 kados read you later
19:44 kados chris when you're back
19:44 kados I replaced the ParseDate and UnixDate with:
19:44 kados my @newnewdate = split(/-/,$olddate);
19:44 kados                $newdate = "$newnewdate[1]"."/"."$newnewd​ate[2]"."/"."$newnewdate[0]";
19:52 kados it doesn't seem to have changed the percentage:
19:52 kados 26.2   0.230  0.269      4   0.0575 0.0673  C4::Date::BEGIN 10.2   0.090  0.705     12   0.0075 0.0587  main::BEGIN
19:53 kados chris when you're back
19:54 kados I replaced the ParseDate and UnixDate with:
19:54 chris2 kados: i reckon its because it still has the use date::manip
19:54 kados ahh
19:54 chris2 if you do a man dprofpp
19:54 chris2 are there any options that make it tell you the function
19:54 chris2 not just the module
19:54 kados I'll check
19:54 chris2 koha.org/irc/
19:55 kados hehe
19:55 chris2 im at a wireless convention thingy
19:55 kados ahh
19:55 kados sweet
19:55 kados whereat?
19:55 chris2 in wellington at the museum here
19:55 kados -t   Display subroutine call tree to stdout.  Subroutine statistics
19:55 kados            are not displayed.  When a function is called multiple consecu-
19:55 kados            tive times at the same calling level then it is displayed once
19:55 kados            with a repeat count.
19:56 chris2 cool lets try that
19:56 kados ok
19:56 chris2 might tell use exactly what subroutines are taking the time
19:56 kados yikes ... lots of data there ... let me port it
19:57 kados huh ... doesn't seem to take > as an argument very well
19:58 chris2 hmm | less work?
20:00 kados it doesn't seem to be showing times with this -t
20:00 kados but this output is HUGE
20:00 kados there must be alot of stuff going on here
20:01 kados http://kados.org/dprof.txt
20:01 kados that's most of it
20:02 kados not quite what we're looking for I think
20:03 kados btw:
20:03 kados The dprofpp tool can also run the profiler before analyzing the pro-       file data.  The above two commands can be executed with one dprofpp       command.
20:03 kados dprofpp -u -p test.pl
20:05 chris2 sorry had a person to talk to
20:05 kados np
20:05 kados I'm in no hurry here ;-)
20:05 chris2 i think there are some options that rank the subroutines in order of most time
20:06 chris2 thats what we are after i think
20:06 kados -v   Sort by average time spent in subroutines during each call.
20:06 chris2 right -t -v maybe?
20:07 chris2 or maybe not the -t bit
20:07 kados -t seems to drop the times
20:07 chris2 right
20:07 kados -v just looks like before
20:08 kados 26.2   0.230  0.269      4   0.0575 0.0673  C4::Date::BEGIN
20:08 chris2 right
20:08 chris2 and i suspect the BEGIN is so big cos thats where the use Date::Manip bit is
20:08 chris2 what happens if u comment that out?
20:08 kados yea ... I'm going to take it out
20:10 kados nice
20:10 kados 37.8   0.329  0.497     10   0.0329 0.0497  C4::Circulation::Circ2::BEGIN
20:10 kados 10.3   0.090  0.685     12   0.0075 0.0571  main::BEGIN
20:10 kados so that's it then
20:10 chris2 right that dropped the total time a lot eh?
20:11 kados yea ...
20:11 chris2 sweet
20:12 chris2 so we have to just test we arent munging dates
20:12 kados yea ... i wonder how we do that ;-)
20:12 kados I know of one way ;_0
20:12 chris2 ie, on a test machine issue some items make sure its doing the right thing
20:12 kados yea
20:12 chris2 and i guess return
20:12 chris2 we should do a grep
20:12 kados yea I was just about to do taht ...
20:13 chris2 cool
20:14 chris2 might even speed up searches, or at least the detail
20:14 chris2 ok im gonna go get some lunch
20:15 kados hmmm, tims isn't much better:
20:15 kados real    0m0.891suser    0m0.849ssys     0m0.040s
20:15 kados cool ... have fun
20:16 kados I'll keep hacking away here ;-)
07:13 paul salut sylvain.
07:13 paul (hdl à coté de moi aujourd'hui.
07:13 paul )
07:14 paul (le bouton dictionnaire avance bien. L'algo est OK je pense, reste à débugger et à coder tout ca proprement...)
07:15 Sylvain cool :)
07:15 Sylvain et bonjour à vous !
07:17 paul et le voilà... on pourra causer par chat si on n'arrive pas à parler tous les 2 :-D
07:17 Sylvain :)
09:53 paul 'morning owne
09:53 paul (owen
09:53 paul )
09:53 owen Hi paul
09:54 owen Is the weather getting warm there yet?
09:55 paul oh yes !
09:56 paul something like 21°C today, with a blue sky.
09:56 paul (did TV speak of Airbus A380 1st flight that was 6 hours ago ?)
09:57 paul (here in france, it seems we have won a world cup of some famous sport like soccer or rubgy ! not less)
09:59 owen http://blogs.guardian.co.uk/ne[…]/flying_high.html

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