I recently added an spaced-repetition functionality to my Japanese quiz app, and one of the requirements of that is to save the next review date into a review schedule table. One of the drawbacks of this is a discernable pause - 2 or 3 seconds - while it inserts or updates the row. So, in this post I'm going to try to figure out of there any way to bring this down. The first thing I'm going to do is time how much of this update is included outside of my app. If it's most of it, which is probable, then I can maybe look at indexes. Also, if theres a significant difference between update and delete, I could pre-populate the schedule.
Anyway, I only have one index on the table I'm inserting to, which is next date. I wonder what kind of impact it would have to get rid of it?
First let's add the timing measurements.
Something like this:
http://www.velocityreviews.com/forums/t144194-measuring-the-execution-time-of-a-java-method.html
long start = System.currentTimeMillis();
....
doSomething();
....
long end = System.currentTimeMillis();
System.out.println("Execution time was "+(end-start)+" ms.");
Ok, this is a pretty good indication:
D/UpdateSRSUtil( 4399): Update execution time was 0 ms.
D/UpdateSRSUtil( 4399): Insert execution time was 1968 ms.
D/UpdateSRSUtil( 4399): Method execution time was 1986 ms.
/UpdateSRSUtil( 4399): Update execution time was 0 ms.
D/UpdateSRSUtil( 4399): Insert execution time was 1115 ms.
D/UpdateSRSUtil( 4399): Method execution time was 1144 ms.
D/UpdateSRSUtil( 4399): Insert execution time was 528 ms.
D/UpdateSRSUtil( 4399): Method execution time was 531 ms.
Interesting. It really goes down with each insert.
D/UpdateSRSUtil( 4399): Insert execution time was 1060 ms.
D/UpdateSRSUtil( 4399): Method execution time was 1063 ms.
Back up on this one.
Ok, I got a couple wrong. Let's see how the insert goes:
D/UpdateSRSUtil( 4399): Update execution time was 705 ms.
D/UpdateSRSUtil( 4399): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4399): Method execution time was 716 ms.
D/UpdateSRSUtil( 4399): Update execution time was 699 ms.
D/UpdateSRSUtil( 4399): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4399): Method execution time was 711 ms.
That's much better.
Let's open it up to existing rows, just to see how the average update goes.
Set the date to 4/1/2012 (I better not forget to reset that, and get out of airplane mode).
D/UpdateSRSUtil( 4472): Update execution time was 1774 ms.
D/UpdateSRSUtil( 4472): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4472): Method execution time was 1864 ms.
D/InitUtils( 4472): saveState
Ouch.
D/UpdateSRSUtil( 4472): Update execution time was 1424 ms.
D/UpdateSRSUtil( 4472): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4472): Method execution time was 1466 ms.
D
Ok, maybe the problem is I haven't set an index on _id. Yes, that might do the trick.
Added the index
I/Database( 4590): sqlite returned: error code = 11, msg = database corruption found by source line 39134
I/Database( 4590): sqlite returned: error code = 11, msg = database corruption found by source line 39172
I/Database( 4590): sqlite returned: error code = 11, msg = prepared statement aborts at 12: [SELECT _id, level, number, kanji, hiragana, english, level_freq_sequence FROM v_all_words_by_level_freq_sequence WHERE level = ?]
E
Why did that happen? Did I screw up the install routine? Try it again.
Hmmm. It worked. Suspicious.
Ok, try it again.
D/UpdateSRSUtil( 4692): Update execution time was 2451 ms.
D/UpdateSRSUtil( 4692): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4692): Method execution time was 2552 ms.
D/InitUtils( 4692): saveState
Yowch. It's worse.
/UpdateSRSUtil( 4692): Update execution time was 1901 ms.
D/UpdateSRSUtil( 4692): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4692): Method execution time was 1975 ms.
D/UpdateSRSUtil( 4692): Update execution time was 1902 ms.
D/UpdateSRSUtil( 4692): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4692): Method execution time was 1968 ms.
D/
The question is, are the indexes helping or hurting? Right now, it doesn't look so great. But later on, it could make a difference.
Get rid of it for now:
D/UpdateSRSUtil( 4794): Insert execution time was 1691 ms.
D/UpdateSRSUtil( 4794): Method execution time was 1700 ms.
D/UpdateSRSUtil( 4794): Insert execution time was 1279 ms.
D/UpdateSRSUtil( 4794): Method execution time was 1289 ms.
D/UpdateSRSUtil( 4794): Update execution time was 731 ms.
D/UpdateSRSUtil( 4794): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4794): Method execution time was 1427 ms.
Hm? Why did the method suddenly take up so much time?
Here's why - look at this date:
1098 4 428 動物園 どうぶつえん zoo 627 2012-04-01 2034-09-29
So, what could've caused that crazy date?
Well, the good news is I have a bunch of debug statements I can turn on, and I just loaded this. So, I'll delete and reload the database, after turning on the debug statements in the date routine.
D/UpdateSRSUtil( 4862): Update execution time was 0 ms.
D/UpdateSRSUtil( 4862): Insert execution time was 1574 ms.
D/UpdateSRSUtil( 4862): Method execution time was 1614 ms.
D/
/UpdateSRSUtil( 4862): Update execution time was 0 ms.
D/UpdateSRSUtil( 4862): Insert execution time was 869 ms.
D/UpdateSRSUtil( 4862): Method execution time was 900 ms.
D
D/UpdateSRSUtil( 4862): Update execution time was 0 ms.
D/UpdateSRSUtil( 4862): Insert execution time was 2047 ms.
D/UpdateSRSUtil( 4862): Method execution time was 2059 ms.
D/UpdateSRSUtil( 4862): Update execution time was 0 ms.
D/UpdateSRSUtil( 4862): Insert execution time was 1212 ms.
D/UpdateSRSUtil( 4862): Method execution time was 1249 ms.
D/
D/DateUtils( 4862): date after loop is: 2012-04-06
D/UpdateSRSUtil( 4862): Update execution time was 0 ms.
D/UpdateSRSUtil( 4862): Insert execution time was 1041 ms.
D/UpdateSRSUtil( 4862): Method execution time was 1055 ms.
Here we go:
D/UpdateSRSUtil( 4862): Secs Remaining: 7
D/UpdateSRSUtil( 4862): dateDiff: 4108
D/DateUtils( 4862): ===================================== adDaysToDate ================
D/DateUtils( 4862): inDate : 2012-04-01 daysToAdd: 8216
D/DateUtils( 4862): >>>>>>>>>>>>>>>>>>>>>>> date1 is: 2012-04-01
D/DateUtils( 4862): s>>>>>>>>>>>>>>>>>>>>>> startDate is: 2012-04-01
D/DateUtils( 4862): >>>>>>>>>>>>>>>>>>>>>>>>> date is: 2012-04-01
D/DateUtils( 4862): date after loop is: 2034-09-29
D/UpdateSRSUtil( 4862): Update execution time was 1572 ms.
D/UpdateSRSUtil( 4862): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4862): Method execution time was 2251 ms.
D
Good luck - it's on exactly the same character. So, the problem is in the date-diff routine.
Ok, - here's the problem - it's a test data issue:
1098 2001-01-01 2011-07-19
So, where starting out with like a 10 year difference. I wonder if I should put a cap on the days difference, like say six months or something. Another issue is there is really no way to look at the words you have reviewed already. I was thinking about adding a "non-srs" mode, which just let's you look at whatever you want. It would just be probably 1/2 days work. If that. I think I need that one extra feature. It's practically done already.
Well, let's take care of this problem, first. Delete the test date, don't need that anymore. Also delete the column index. Now, let's see how it runs.
D/UpdateSRSUtil( 4953): Insert execution time was 1082 ms.
D/UpdateSRSUtil( 4953): Method execution time was 1086 ms.
D/UpdateSRSUtil( 4953): Update execution time was 0 ms.
D/UpdateSRSUtil( 4953): Insert execution time was 1867 ms.
D/UpdateSRSUtil( 4953): Method execution time was 1890 ms.
D/InitUtils( 4953): saveState
D/InitUtils( 4953): appState.currentQuest
D/UpdateSRSUtil( 4953): Update execution time was 0 ms.
D/UpdateSRSUtil( 4953): Insert execution time was 869 ms.
D/UpdateSRSUtil( 4953): Method execution time was 884 ms.
D/InitUtils( 4953): saveState
D/
D/UpdateSRSUtil( 4953): Secs Remaining: 7
D/UpdateSRSUtil( 4953): Update execution time was 0 ms.
D/UpdateSRSUtil( 4953): Insert execution time was 1717 ms.
D/UpdateSRSUtil( 4953): Method execution time was 1721 ms.
D
D/UpdateSRSUtil( 4953): Update execution time was 0 ms.
D/UpdateSRSUtil( 4953): Insert execution time was 1723 ms.
D/UpdateSRSUtil( 4953): Method execution time was 1735 ms.
D/UpdateSRSUtil( 4953): ========================== SRS ===========================
D/UpdateSRSUtil( 4953): Secs Remaining: 7
D/UpdateSRSUtil( 4953): Update execution time was 876 ms.
D/UpdateSRSUtil( 4953): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4953): Method execution time was 887 ms.
D/InitUtils( 4953): saveState
D
D/UpdateSRSUtil( 4953): Update execution time was 1646 ms.
D/UpdateSRSUtil( 4953): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4953): Method execution time was 1654 ms.
D/UpdateSRSUtil( 4953): Update execution time was 1701 ms.
D/UpdateSRSUtil( 4953): Insert execution time was 0 ms.
D/UpdateSRSUtil( 4953): Method execution time was 1730 ms.
Well, I suppose it's tolerable. I think I'll program a non-SRS mode if people just want to go over the question at their own rate, or just look back at question etc.
No comments:
Post a Comment