← Previous day | Today | Next day → | Search | Index
All times shown according to UTC.
| Time | Nick | Message |
|---|---|---|
| 16:12 | kados | "600a", # SUBJECT ADDED ENTRY--PERSONAL NAME |
| 16:12 | "610a", # SUBJECT ADDED ENTRY--CORPORATE NAME | |
| 16:12 | "611a", # SUBJECT ADDED ENTRY--MEETING NAME | |
| 16:12 | "630a", # SUBJECT ADDED ENTRY--UNIFORM TITLE | |
| 16:12 | "650a", # SUBJECT ADDED ENTRY--TOPICAL TERM | |
| 16:12 | "651a", # SUBJECT ADDED ENTRY--GEOGRAPHIC NAME | |
| 16:38 | let's bring owen into this | |
| 16:38 | chris | owen: how much flash do you know? |
| 16:38 | :) | |
| 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 | I saw it too | |
| 16:40 | 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 | 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 | maybe for a few hours | |
| 16:42 | issues table is now 1/3 it's original size | |
| 16:42 | so I don't this it's that | |
| 16:42 | the reserves table is pretty big though | |
| 16:42 | 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 | 22682 | |
| 16:43 | hehe | |
| 16:43 | sorry about that | |
| 16:43 | chris | i dont think that would be it |
| 16:44 | thats pretty small in the scheme of things | |
| 16:44 | kados | select count(*) from statistics; |
| 16:44 | 2300680 | |
| 16:44 | 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 | 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 | pretty much every query | |
| 16:46 | related to searching | |
| 16:47 | chris | did you try bringing it back up in the old kernel? |
| 16:47 | kados | yep |
| 16:47 | no change | |
| 16:47 | I even tried running 'repair table' on marc_word | |
| 16:47 | 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 | now they're 5-6 seconds | |
| 16:48 | 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 | load average: 1.98, 1.12, 0.96 | |
| 16:49 | average is usually under 1 | |
| 16:49 | (this is a busy time of the day) | |
| 16:49 | chris | right |
| 16:50 | 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 | when no searchings were going through | |
| 16:51 | it was taking 2-3 secs | |
| 16:51 | that's with top configured to reset every .1 secs | |
| 16:51 | chris | yep, thats not a real test tho |
| 16:51 | since top loads the machine up | |
| 16:51 | kados | I know ;-) |
| 16:51 | chris | and its also being run thru the webserver |
| 16:51 | 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 | 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 | how do I pass the cgi? | |
| 16:53 | chris | there is some way you can pass parameters in |
| 16:54 | 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 | I'm not signed up there ... chris are you? | |
| 16:56 | chris | your_script.pl name1=value1 name2=value2 |
| 16:56 | i used to be a long time ago | |
| 16:57 | kados | so ... |
| 16:57 | ./circulation.pl findborrower-0054313 | |
| 16:57 | chris | wed have to disable the auth check |
| 16:57 | cos it wont be able to fetch the cookie | |
| 16:57 | 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 | real 0m0.650s | |
| 16:59 | 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 | can we do strace on it? | |
| 17:01 | chris | we can do the perl equivalent |
| 17:01 | 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 | % perl -d:DProf store_archive | |
| 17:08 | kados | sweet |
| 17:09 | 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 | ahh | |
| 17:11 | chris | and drop the time as well :) |
| 17:12 | 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 | and ull see something like that | |
| 17:13 | this | |
| 17:13 | kados | http://kados.org/tmon.out |
| 17:13 | chris | Total Elapsed Time = 0.762654 Seconds |
| 17:13 | User+System Time = 0.492654 Seconds | |
| 17:13 | Exclusive Times | |
| 17:13 | %Time ExclSec CumulS #Calls sec/call Csec/c Name | |
| 17:13 | 22.3 0.110 0.130 4 0.0275 0.0324 C4::Date::BEGIN | |
| 17:14 | the tmon.out file wont tell us anything until we run | |
| 17:14 | dbprofpp | |
| 17:14 | so dprofpp | |
| 17:14 | kados | command not found |
| 17:14 | chris | hmm |
| 17:14 | kados | ahh ... I mispelled |
| 17:14 | chris | dprofpp |
| 17:14 | it is | |
| 17:14 | i keep wanting to put a b in it :) | |
| 17:15 | kados | http://kados.org/dprof.txt |
| 17:15 | chris | right |
| 17:15 | C4::Date took 28% of the time | |
| 17:16 | kados | interesting |
| 17:16 | chris | and for me 22% |
| 17:16 | so that looks to be the culprit | |
| 17:16 | kados | so that's a problem ;-) |
| 17:16 | we don't care that much about the time ;- | |
| 17:16 | wow ... this is really cool | |
| 17:16 | I can do this will all the scripts | |
| 17:17 | thanks for showing me | |
| 17:17 | chris | no problem |
| 17:17 | i reckon its date::manip | |
| 17:18 | Total Elapsed Time = 0.857364 Seconds | |
| 17:18 | User+System Time = 0.837364 Seconds | |
| 17:18 | thats not too bad tho | |
| 17:18 | 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 | 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 | using localtime(time) | |
| 17:21 | chris | hmm |
| 17:21 | kados | here's a snip from some code I've already written: |
| 17:21 | my ($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) | |
| 17:21 | = localtime(time); | |
| 17:21 | $year +=1900; | |
| 17:21 | $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 | but | |
| 17:22 | format_date takes a date (presumably one just fetched from mysql) | |
| 17:23 | and formats it as mm/dd/yy or yy/mm/dd or dd/mm/yy | |
| 17:23 | 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 | as long as the dates are coming from mysql | |
| 17:23 | cos they will always be in the format yyyy-mm-dd | |
| 17:23 | 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 | k | |
| 17:24 | thanks chris! | |
| 17:24 | chris | good luck |
| 17:24 | kados | read you later |
| 19:44 | chris when you're back | |
| 19:44 | I replaced the ParseDate and UnixDate with: | |
| 19:44 | my @newnewdate = split(/-/,$olddate); | |
| 19:44 | $newdate = "$newnewdate[1]"."/"."$newnewdate[2]"."/"."$newnewdate[0]"; | |
| 19:52 | it doesn't seem to have changed the percentage: | |
| 19:52 | 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 | chris when you're back | |
| 19:54 | 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 | are there any options that make it tell you the function | |
| 19:54 | 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 | sweet | |
| 19:55 | whereat? | |
| 19:55 | chris2 | in wellington at the museum here |
| 19:55 | kados | -t Display subroutine call tree to stdout. Subroutine statistics |
| 19:55 | are not displayed. When a function is called multiple consecu- | |
| 19:55 | tive times at the same calling level then it is displayed once | |
| 19:55 | 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 | 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 | but this output is HUGE | |
| 20:00 | there must be alot of stuff going on here | |
| 20:01 | http://kados.org/dprof.txt | |
| 20:01 | that's most of it | |
| 20:02 | not quite what we're looking for I think | |
| 20:03 | btw: | |
| 20:03 | 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 | dprofpp -u -p test.pl | |
| 20:05 | chris2 | sorry had a person to talk to |
| 20:05 | kados | np |
| 20:05 | 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 | 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 | 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 | 26.2 0.230 0.269 4 0.0575 0.0673 C4::Date::BEGIN | |
| 20:08 | chris2 | right |
| 20:08 | and i suspect the BEGIN is so big cos thats where the use Date::Manip bit is | |
| 20:08 | what happens if u comment that out? | |
| 20:08 | kados | yea ... I'm going to take it out |
| 20:10 | nice | |
| 20:10 | 37.8 0.329 0.497 10 0.0329 0.0497 C4::Circulation::Circ2::BEGIN | |
| 20:10 | 10.3 0.090 0.685 12 0.0075 0.0571 main::BEGIN | |
| 20:10 | 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 | so we have to just test we arent munging dates | |
| 20:12 | kados | yea ... i wonder how we do that ;-) |
| 20:12 | 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 | we should do a grep | |
| 20:12 | kados | yea I was just about to do taht ... |
| 20:13 | chris2 | cool |
| 20:14 | might even speed up searches, or at least the detail | |
| 20:14 | ok im gonna go get some lunch | |
| 20:15 | kados | hmmm, tims isn't much better: |
| 20:15 | real 0m0.891suser 0m0.849ssys 0m0.040s | |
| 20:15 | cool ... have fun | |
| 20:16 | I'll keep hacking away here ;-) | |
| 07:13 | paul | salut sylvain. |
| 07:13 | (hdl à coté de moi aujourd'hui. | |
| 07:13 | ) | |
| 07:14 | (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 | 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 | (owen | |
| 09:53 | ) | |
| 09:53 | owen | Hi paul |
| 09:54 | Is the weather getting warm there yet? | |
| 09:55 | paul | oh yes ! |
| 09:56 | something like 21°C today, with a blue sky. | |
| 09:56 | (did TV speak of Airbus A380 1st flight that was 6 hours ago ?) | |
| 09:57 | (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 |
← Previous day | Today | Next day → | Search | Index