rupert.thurner wrote: > can the times between the debug statements also taken as performance > points? if yes, then the following is slow here: > 1. retrieving the session id > taking up to 5 seconds, on the third click coming down. > 2. update wiki page index > taking up to 5 seconds, and happening quite often when only > clicking once > there is " if now > self._last_index_update + > WikiSystem.INDEX_UPDATE_INTERVAL:" > which is set to 5 sec - but for us 10 minutes are sufficient i > guess. > > log excerpt 1, one click on main wiki page: > > 2009-08-09 00:31:09,282 Trac[main] DEBUG: Dispatching <Request "GET u'/ > wiki'"> > 2009-08-09 00:31:09,700 Trac[api] DEBUG: action controllers for ticket > workflow: ['ConfigurableTicketWorkflow'] > 2009-08-09 00:31:09,868 Trac[svn_fs] DEBUG: Subversion bindings > imported > 2009-08-09 00:31:09,912 Trac[chrome] DEBUG: Prepare chrome data for > request > 2009-08-09 00:31:10,151 Trac[api] DEBUG: Updating wiki page index > 2009-08-09 00:31:10,180 Trac[session] DEBUG: Retrieving session for ID > 'rupert.thurner' > 2009-08-09 00:31:12,958 Trac[formatter] DEBUG: Executing Wiki macro > TracNav by provider <tracnav.tracnav.TracNav object at 0x16d6eb0> > >
No, there's no rule currently about when we write the debug statements. Here, "Updating wiki page index" is written before updating the index, so all we know is that the duration of this operation is less than 29 ms... as the "Retrieving session for ID" is unrelated. But the retrieval of a session doesn't take 2.7 seconds ... the "Execute Wiki macro" is output during the template generation, as the wiki_to() calls are triggered there. I'm not sure, but I don't think that systematic start/stop debug output will help. Maybe we could do this in a few selected places, though, in order to help spot the potential problems (e.g. those listed in the new TracPerformance page). A bit in the spirit of http://trac.edgewall.org/changeset/7322, but more systematic (e.g. "mail submitted (took ... seconds)"). > log excerpt 2, one click on timeline: > the funny thing the double entry, the second time happening while the > page is already displayed on the browser. > > 2009-08-08 23:50:33,749 Trac[main] DEBUG: Dispatching <Request "GET u'/ > timeline'"> > 2009-08-08 23:50:33,807 Trac[session] DEBUG: Retrieving session for ID > 'rupert.thurner' > 2009-08-08 23:50:35,841 Trac[chrome] DEBUG: Prepare chrome data for > request > 2009-08-08 23:50:36,049 Trac[api] DEBUG: Updating wiki page index > 2009-08-08 23:50:41,081 Trac[api] DEBUG: Updating wiki page index > 2009-08-08 23:50:45,150 Trac[main] DEBUG: Dispatching <Request "GET u'/ > timeline'"> > 2009-08-08 23:50:45,197 Trac[session] DEBUG: Retrieving session for ID > 'rupert.thurner' > 2009-08-08 23:50:51,241 Trac[chrome] DEBUG: Prepare chrome data for > request > 2009-08-08 23:50:51,607 Trac[api] DEBUG: Updating wiki page index > Were you using Firefox? Firefox often sends one more request than necessary, though usually only for rel="next" links (see https://developer.mozilla.org/en/Link_prefetching_FAQ). The "/timeline" page normally doesn't contain such a next link, only when you browse at an older date, but that would be visible in the GET url. Maybe some Firefox plugin is triggering this (try disabling them)? Alternatively, you may have subscribed a RSS feed on the timeline which by chance fired a request at the same time... -- Christian --~--~---------~--~----~------------~-------~--~----~ You received this message because you are subscribed to the Google Groups "Trac Development" group. To post to this group, send email to [email protected] To unsubscribe from this group, send email to [email protected] For more options, visit this group at http://groups.google.com/group/trac-dev?hl=en -~----------~----~----~----~------~----~------~--~---
