Slow processings

[rafamanzo]

Running the following on mezuro.org console gives us an hint of why some processings take so long

=> ProcessTime.all.group('state').average('time').map { |k,v| {k => v.to_f/60.0} }

=> [
  {"PREPARING"=>0.0021892476280869332},
  {"CHECKING"=>2.1039809739626834},
  {"AGGREGATING"=>29.408375646260332},
  {"BUILDING"=>0.919068727626195},
  {"INTERPRETING"=>1.7958658936723333},
  {"DOWNLOADING"=>0.20159135590306834},
  {"CALCULATING"=>3.2441646428687334},
  {"COLLECTING"=>4.56774077964555}
]

It means that on average each Processing takes approximately 30min aggregating.

By looking at the database machine processor we can see it at 100% full time during aggregation.

I suggest:

• Create benchmarks for aggregation
  • Aggregation performance #211
• Investigate the benchmark results
  • pgBadger
  • See how much time each method call takes with RubyProf::CallStackPrinter
• Write some cache and fixes where is possible to do so
  • Bulk insertions of TreeMetricResults bottom-up
    • With bulk insertions, adding more indexes to the metric_results table may be worth the extra insertion cost. We need to investigate that once the bulk insertions are up.
    • Bulk insert aggregated results #225
  • Improve TreeMetricResult#descendant_values performance
    • Optimize TreeMetricResult#descendant_values #224
  • Propose database indexes (Investigate database indexes impact on data listing #229)

[rafamanzo]

Some work for producing performance tests has been started at the following branch: https://github.com/mezuro/kalibro_processor/tree/aggregation_performance

[rafamanzo]

I've added tests to Aggregator with similar complexity to the one found at mezuro.org: ced0eee

But the results are still not close to be that slow with an mean run time of 0.55s.

Insights are welcome @mezuro/core 😄

[danielkza]

We'd probably need to test with a high concurrency level if the database itself is being the bottleneck. I think profiling the queries through PostgreSQL would be the easier way to understand the issues - we can look at the query plans and query times using something like pgBadger.

[rafamanzo]

On mezuro.org there is a single worker generating workloads to the database, so I don't believe we'll replicate the issue with concurrency. But I've tested with a single MetricResult. Perhaps it is worth to increase its count on the test as mezuro.org issues happen with configurations holding at least half dozen metrics.

About pgBadger looks like a nice tool to use once we can produce a test that replicates the issues found at mezuro.org.

[danielkza]

I thought we had four workers for kalibro_processor, my mistake!

[rafamanzo]

I've fixed the perfomance test. It was fast because I missed proper data initialization.

Now I have the following for a tree with height 10 and 2 children per node, so 512 leafs. Then I've produced the following:

Metric Count	Wall Time (s)	Process Time (s)
1	8.672761964797974	7.54611889
2	14.596535205841064	24.3851091414
4	77.55368666648864	127.275106022
8	256.8674069881439	556.1682938326

Running with 8 metrics still not produced the 100% usage by postgresql seen at mezuro.org. The plot looks quadratic.

[rafamanzo]

Possible cause: https://github.com/mezuro/kalibro_processor/blob/master/lib/processor/aggregator.rb#L23. @danielkza pointed out that the MetricResults table has no indexation which make the repetition of such query really slow.

[diegoamc]

I've run the same tests as @rafamanzo and have got the following results:

Metric Count	Wall Time (s)	Process Time (s)
1	6.992499828338623	7.272484427600001
2	13.529412364959716	12.9735503228
4	26.20373945236206	28.432685047400003
8	62.70585794448853	64.16384417580001

Then, I've created indexes on the columns module_result_id and metric_configuration_id of table metric_results and rerun the same tests. The following are the results for them:

Metric Count	Wall Time (s)	Process Time (s)
1	6.903397846221924	7.131537662599999
2	13.142084169387818	13.2359803324
4	28.782897806167604	28.8164754306
8	64.86161379814148	56.7507790644

From these results, I don't think the lack of indexes are the main problem for such sluggish processings.
However, I also have some doubts about my tests. First, my results are much faster than @rafamanzo's. What could be the reasons for that? Just processing power?

Another thing, could the metrics used affect the results? I've commented the metrics I wouldn't use on the test from bottom to top (given the order on the performance script). Is this how you did too, @rafamanzo?

Also, it is recommended to someone else corroborate these results. I've commited the changes and pushed a new branch called metric_result_indexes. The commit goes with the modified database schema, so a single rollback is needed to return the database to its previous state (without the indexes).

Finally, if the results are corroborated, I think the reason for the indexes to not affect the performance is that we make to many insertions on MetricResult's table. Note, we are using a b-tree as the index structure. On those structures, searches are greatly improved. The searching algorithm goes from O(n) to O[t*log(n)], where t is the number os elements in each node of a b-tree. However, insertions become slower. The insertion algorithm goes from O(1) to O[log(n)]. Therefore, making a lot of insertions on the table, which is our case (on the script setup, with 8 metrics, we create 8184 metric results), is not recommended. That is because the time gained by a faster searching may be compensated by a slower insertion. In my opinion, that is what the results are showing. We can only conclude that the sluggish performance of the aggregation state is not due to lack of indexes on the MetricResult's table. Reference for b-tree's algorithms and time complexities I used here.

What do you think?

[rafamanzo]

From branch metric_result_indexes I've got the following on the same hardware as the previous tests:

Metric Count	Wall Time (s)	Process Time (s)
1	7.591419649124146	12.0535053682
2	31.928905773162843	39.1385960514
4	74.23858404159546	140.50534778839997
8	247.94011964797974	535.5620568106

Starting from 4 metrics one CPU have become pinned at 100% usage. But not by postgres. The aggregation itself was using 100% of one CPU.

Looks like this test is stressing some other performance issue rather than the missing indexes that we need to address before setting those up. But I believe they will play an important role afterwards on the large database we have at mezuro.org. They actually look to have eased some load on my machine starting at 4 metrics.