Investigate Evaluator performance

[luoyanjie]

With logging added, dig deep into the data and find out where the bottleneck is.

[fonglh]

Evaluator Slave Statistics

The evaluator slave performs the actual evaluation. Before it can do so, it needs to get an evaluation job, fetch the package, pull and create the docker container.

After running the evaluation, it saves the result back to the app server.

The results here are from analysing the log files over the past week or so.

###### allocate ######
Minimum: 82.81
Maximum: 6419.066
Average: 207.30644962042763
Median: 188.5435
95th percentile: 335.7475
Count: 8694

###### fetch_package ######
Minimum: 70.793
Maximum: 3413.976
Average: 176.11723027375217
Median: 162.983
95th percentile: 259.25815
Count: 8694

###### pull ######
Minimum: 0.127
Maximum: 55772.413
Average: 44.765413963653046
Median: 0.331
95th percentile: 0.578
Count: 8694

###### create ######
Minimum: 16.301
Maximum: 283.507
Average: 41.43743846330806
Median: 41.5665
95th percentile: 66.28125
Count: 8694

###### evaluator_evaluate ######
Minimum: 492.092
Maximum: 57220.276
Average: 1160.839555440528
Median: 988.968
95th percentile: 1742.0364
Count: 8694

###### save ######
Minimum: 72.709
Maximum: 22825.079
Average: 214.6062727481879
Median: 190.882
95th percentile: 358.6644
Count: 8693

###### total_duration ######
Minimum: 873.373
Maximum: 113585.13799999999
Average: 1845.0476760984666
Median: 1587.2465
95th percentile: 2584.6487
Count: 8694

###### percent_evaluate ######
Minimum: 9.769843568683612
Maximum: 98.24752833194738
Average: 61.100965616059725
Median: 61.839798138
95th percentile: 72.662017144
Count: 8694

Total allocation checks: 405181
Successful allocations: 8695
Percentage of successful allocations: 2.1459545240275335%
Seconds waiting: 619838.0
Seconds busy: 13649.0
Percentage busy time: 2.1545824934055475%

Conclusions

The evaluator processes are idle most of the time.
Most evaluations complete in 2.5 seconds, so the extra time observed by the client is outside of the evaluator.
Within the evaluator slave, 60+% of the total time taken is spent on actually evaluating the code.

[fonglh]

Instrumentation

These instrumentation events are deployed for our production instance. The initializer is not in this open source repository.

On the app server:

1. submit_answer
   1. grade_and_reattempt

On the worker:

1. grade in AutoGradingService
   1. evaluate in ProgrammingAutoGradingService
      1. evaluate_answer
         1. wait_for_evaluation

On the evaluator slave:

See the steps above. At the end of those actions,

1. save
   1. update_result on the app server

Thus the wait time for evaluator polling is the difference between wait_for_evaluation on the worker and the total amount of time the evaluator takes (allocate, pull, create, ...) for the same evaluation_id.

[benleong]

2.5 s for evaluation is still v slow. Can we try to figure out how to bring it down to < 1 s? Also, have we taken the MCQs and MRQs out of the evaluator?

…

On Fri, Apr 28, 2017 at 10:03 AM, fonglh ***@***.***> wrote: Instrumentation On the app server: 1. submit_answer 1. grade_and_reattempt On the worker: 1. grade in AutoGradingService 1. evaluate in ProgrammingAutoGradingService 1. evaluate_answer 1. wait_for_evaluation On the evaluator slave: See the steps above. At the end of those actions, 1. save 1. update_result on the app server Thus the wait time for evaluator polling is the difference between wait_for_evaluation on the worker and the total amount of time the evaluator takes (allocate, pull, create, ...) for the same evaluation_id. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#2122 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABPMdUrMqN0x7GhYJwhTNOdzw9kHFmYRks5r0Z1QgaJpZM4MVDcs> .

[fonglh]

From a sample set of graylog data, the poll wait time was calculated using the method outlined above (Difference between wait_for_evaluation and total evaluator time).

About 1/4 of the values were negative. Leaving out these invalid values, the average poll wait time is
about 1338 ms.

Detailed analysis:

Total lines:  2223
Valid lines:  1568
Valid %:  70.5353126405758
Minimum poll wait:  1.147
Maximum poll wait:  15601.785
Average poll wait:  1337.5390465561231
Median poll wait:  741.488
95th percentile:  5479.7406

[benleong]

1.3 s of poll wait is too long. -- Warmest Regards, Ben - sent from iPhone