Performance
| Case number: | 954892-2005677 |
| Topic: | Developer Preview |
| Opened by: | LociOiling |
| Status: | Open |
| Type: | Bug |
| Opened on: | Tuesday, September 4, 2018 - 04:27 |
| Last modified: | Wednesday, September 12, 2018 - 23:40 |
The new devprev release seems a bit sluggish at times, so I tried
comparing 20180829-6ed3ad0d20-win_x86-devprev to 20180725-d14dae34c3-win_x86.
On puzzle 1567, I used Rav3n_pl Fuzes v1.5.5 with medium wiggle power.
Starting with a score of 15,345, I ran main and devprev three times, each time increasing the wiggle factor setting used by the recipe. (The Foldit wiggle power setting was medium for all three tests.)
While devprev had a slightly higher score each time, it also took longer.
Interestingly, wiggle factor 4 produced slightly better results than wiggle factor 5, but only by a fraction.
The table below summarizes the results, showing the gain, elapsed time (in hours), and point per hour (PPH) for each test.
While devprev seems a little slower based on this limited testing, the results don't seem to explain the sluggishness I was seeing in 1567. The symptoms included it being difficult to freeze structures by double-clicking on them, an very slow performance in some recipes.
| settings | main | devprev | |||||
|---|---|---|---|---|---|---|---|
| run | wiggle factor | gain | hours | PPH | gain | hours | PPH |
| 1 | 2 | 1816.293 | 0.5 | 3628.554 | 1816.86 | 0.603 | 3008.599 |
| 2 | 4 | 1820.476 | 0.658 | 2766.447 | 1820.801 | 0.807 | 2254.861 |
| 3 | 5 | 1820.172 | 0.662 | 2748.581 | 1820.662 | 0.823 | 2209.839 |
Here's an attempt at a more readable table.
| settings | main | devprev | |||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| run | __ | wiggle factor | __ | gain | __ | hours | __ | PPH | __ | gain | __ | hours | __ | PPH | __ |
| 1 | __ | 2 | __ | 1816.293 | __ | 0.5 | __ | 3628.554 | __ | 1816.86 | __ | 0.603 | __ | 3008.599 | __ |
| 2 | __ | 4 | __ | 1820.476 | __ | 0.658 | __ | 2766.447 | __ | 1820.801 | __ | 0.807 | __ | 2254.861 | __ |
| 3 | __ | 5 | __ | 1820.172 | __ | 0.662 | __ | 2748.581 | __ | 1820.662 | __ | 0.823 | __ | 2209.839 | __ |
Kind of ugly, but maybe a bit more readable than before. Seems like something needs to be updated in Drupal-land.
Does this happen in non symmetry puzzles?
The non-symmetry puzzles seem to be performing normally, but I haven't tried a similar test. I'll do something similar with the current revisiting puzzle and post the results here.
This might be related to the fix for the asymmetry problem. I'll see if I cant improve the performance a bit.
I did some further testing on puzzle 1571, with the solution "1571 performance test base" that's shared with scientists.
I again ran Fuzes on both main and devprev, 10 times each on low and high wiggle power. I set the recipe's wiggle factor to 2 on low wiggle power, and 4 on high wiggle power.
Devprev was just slightly slower on low wiggle power, a 4.65% increase over main. Main actually had a higher average gain by a small fraction.
On high wiggle power, devprev was 11.67% slower, but the average gain was over 13 points higher.
I don't see these differences as being significant, since there seemed to be a mix of slower runs and faster runs. A little bad luck may have skewed the results. I notice that the first devprev run took 9.66 minutes, about 1.5 minutes longer than the next highest time. I'd need to run a lot more tests to conclude there's really a difference.
No table this time, but a spreadsheet-ready CSV file (just drop the .txt) for those who are interested.
Back on 1570, the experience for me is that everything gets slower as the time remaining gets shorter.
I've also noticed an error popup, as seen below:
Wiggle encountered a bug: 'Internal symmetry error' Cancelling tool.
Despite what the message says, it only pops up when I cancel wiggle, it's not as though wiggle stops by itself. It seems to happen regardless of the wiggle power setting.
On one cycle with pose shown, wiggle was producing distorted shapes. When I reverted to the previous position and tried again, wiggle seemed to behave more normally, although very slowly.
When I close the client directly after another wiggle, I see the following "FOLD_TREE" lines in log.txt, and "REPORTING CRASH: 476462". The client appeared to close normally, however, and there's nothing in the Windows event log showing a crash.
FOLD_TREE EDGE 214 216 19 EDGE 214 218 20 EDGE 214 215 21 EDGE 216 217 22 EDGE 218 219 23 EDGE 215 71 16 EDGE 217 142 17 EDGE 219 213 18 EDGE 71 12 1 EDGE 142 83 2 EDGE 213 154 3 EDGE 71 29 4 EDGE 142 100 5 EDGE 213 171 6 EDGE 71 40 7 EDGE 142 111 8 EDGE 213 182 9 EDGE 71 52 10 EDGE 142 123 11 EDGE 213 194 12 EDGE 71 65 13 EDGE 142 136 14 EDGE 213 207 15 EDGE 12 1 -1 EDGE 12 23 -1 EDGE 29 24 -1 EDGE 29 35 -1 EDGE 40 36 -1 EDGE 40 45 -1 EDGE 52 46 -1 EDGE 52 59 -1 EDGE 65 60 -1 EDGE 65 70 -1 EDGE 83 72 -1 EDGE 83 94 -1 EDGE 100 95 -1 EDGE 100 106 -1 EDGE 111 107 -1 EDGE 111 116 -1 EDGE 123 117 -1 EDGE 123 130 -1 EDGE 136 131 -1 EDGE 136 141 -1 EDGE 154 143 -1 EDGE 154 165 -1 EDGE 171 166 -1 EDGE 171 177 -1 EDGE 182 178 -1 EDGE 182 187 -1 EDGE 194 188 -1 EDGE 194 201 -1 EDGE 207 202 -1 EDGE 207 212 -1
REPORTING CRASH: 476462
***** PREMATURELY ENDING THREAD ActionGlobalMinimize
Couldn't quit: Illegal operation for this state (..\..\..\source\src\game\util\IRC.cc:374)
closing boinc...
Sending SOPs:Sending SOPs:
exiting...
done.
Thanks Loci - the 'crash' is actually a bit of a misnomer at this point. We've recently expanded our crash reporting system to also be a general bug reporting system so that we can see when non-critical issues are popping up in players' clients. Our hope is that it can help in some situations like this to track down problems.
We should probably rename it, though.
| Type: Question » Bug |
Ended up with a crash while wiggling, lots of interesting stuff in log.txt, but no debug.txt generated. Upgrading this feedback to bug. A little bit of a change in topic, but it seems related to the issues with this puzzle. I'm giving up on the original subject, since devprev has now been pushed to main. The old main did really seem much better than devprev on puzzle 1570, and devprev/new main are fine on other puzzles.
The log.txt is almost 7,500 lines, so there's a lot to look at.
Early on, it appears to loop for a while while loading the hotkeys.
There are lots of Rosetta warnings, and numerous "Resymmetrized pose" messages.
Currently working on a release which should alleviate the performance problems. Stay tuned!
Sorry that the table is hard to read -- somehow the border attribute didn't get applied to the data rows.
You can copy the table above and paste into a spreadsheet to see the data in a better format.
I'll figure out the table issue tomorrow and post again.