|
History
| Log In
|
|
|
|
I tried it the following way: First, the old user. Slow. Then logout and creation of a new user. Fast.
Without deleting the previous user learner model?
Carsten Ullrich (JIRA) wrote: > [ http://jira.activemath.org//browse/AMATH-746?page=comments#action_12416 Here's a logfile with timing data for requests, and DEBUG only enabled for XLM.
The log contains a test with 3 users: 1 old user with lots of XLM data, 1 fresh user who has only solved 1 exercise, and one new user. The script for the log (you can use the times to find the relevant places in the log): login winter 1 (old user) 15:45:04 go to Up&Down p1, p2 15:47:17 go to Up&Down p1, p2 15:48:48 go to Up&Down p1, p2, p1, p2 The times for "action()" denote the time spent in the controller, without the view rendering. We find that a page view takes 2-6 seconds, but independant of the user (this contradicts what I said in the description, that a new user is "fast as ever"). Doing the same test without XLM enabled for knowledge values (config: xlm.user-mastery.enabled=false") yields controller page view times <500ms. More to come. Here's the log when XLM is disabled for the knowledge values.
Why there are more times taken in the first run than in the second? I guess it is because in the second only one of the three examples (winter 1, 2 and 3) is run.
Some statistics: $ stats -v n min max mean sd < with-xlm-times.dat $ stats -v n min max mean sd < without-xlm-times.dat The difference is, on average, between 0.6 and 2.3 seconds, yet xLM is not much slower in the worse case. I am wondering what the results would be for without-xlm with more data. When a request is made to xLM on a summary belief on content the following process take place:
content-id => top-content-ids => topic-ids => belief-descs => beliefs => single belief => summary. My guess is that the most time consuming task in the process of recovering a belief on content from the learner model is content-id => top-content-ids, because it traverses the 'for' relations up to the top. We could cache this information, yet I think it would be cleaner if the cache is closer to the content; i.e. moving getTopContentIds from XlmModelImpl to somewhere outside xLM (e.g. ContentManager). What do you think? I can definitely reproduce the difference between a new learner and an old learner (without deleting the learner model). You can see it best if you use the first steps of course generation (without generating a course). Simply enter the menu, select any scenario, select the LeAM grouping. For a new learner, the next step (displaying the content) takes place in about 30 seconds, for an old learner it takes more than a minute. I can confirm it when switching between pages, too. In the book up&down, switching between pages (for both learner the same pages) with a new learner takes three seconds, with the old learner about six seconds. I tried this several times, to rule out effects of the cache.
Hi Rafael, basically I think caching is a good idea, but I' not sure that content-id => top-content-ids really is the bottleneck. For-Relations are instanciated lazyly in Item, but once they are fetched, they are stored in Item.
Why not store content-id -> summary once calculated? For quick tests on what takes time, you can use org.activemath.webapp.util.StopWatch: StopWatch sw = new StopWatch("Transformer"); sw.start("Building JDOM document"); sw.start("Loading stylesheet"); System.out.println(sw.prettyPrint()); Regarding Rafaels comment on statistics AMATH-746#action_12421: the logfile with XLM contains many other actions, whereas for the short one without XLM, I only did the test script.
For your statistics, you should only consider the requests to view.cmd. Attaching single-request-with-xlm.log, which is an extract of a single page view from the big log, for further analysis.
Looking at single-request-with-xlm.log, we get 19x "Recovering summary beliefs":
2006-04-27 15:43:11,069 DEBUG model.XlmSession - Gone out (winter, 1)! Each recovering takes in the order 50-200ms (which sums up to our 2000ms request time). Having a look at one recovery, we see that the bulk of time is spent between the last 2 lines, nowhere else: 2006-04-27 15:43:11,491 DEBUG model.XlmModelImpl - Recovering belief on 'winter' on 'mbase://ActiveMath_Content_Examples/example_examples_theory/example_1'. So I think getTopContentIds() is not the culprit. Rafael? OK. I have run a LeActiveMath with stopwatches inside getSummaryBelief, decomposing the time into
(1) recovering root of competency map, I played with LeAM Calculus RecBook, chapter Items for differentiation. I did the first eleven exercises three times, including self report on affect. Then I logged out and logged in again, and open book again. I measured the time it took for LeActiveMath to display the book (on Items for differentiation, being the last chapter I had seen, and the times for recovering summary beliefs. This is a summary of what happened.
TASK MIN MAX MEAN STDEV SUM
This is the log file with stopwatches on getSummaryBelief.
This is XlmModelImpl with the stopwatches in.
Thanks for your analysis, Rafael.
> It is very important to notice that the time consuming task has This is true for almost all performance problems... Maybe Hibernate caching would be a solution?
This still happens despite all optimisation efforts BUT ONLY with users I have been using for a long time. The differences are striking: opening the LeAM TOC for course generation happens instantly for a new users, but takes 30 seconds for my old user.
Yes, XLM is still behaving strangely. There can be long delays, up to a minute.
See also the deadlocks in Things are starting to look bad for the evaluation. |
|||||||||||||||||||||||||||||||||||||||||||||||||||||||
 |
|
Bug
Closed
Critical
XLM slows down application over time
Rafael