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