Skip to content

Draft: CI: Profile factory creations and SQL queries via EventProf

Peter Leitzen requested to merge pl-event-prof-json-report into master

What does this MR do and why?

This is a proof of concept (hence Draft) to investigate which specs create the most factory and run most SQL queries and thus are slow.

Related:

It tracks amount of factory creations and SQL queries in all RSpec tests via test-prof's EventProf as JSON.

Results

  {
    "fields": [
      {"key": "type", "label": "Type", "sortable": true},
      {"key": "count", "label": "Factories created", "sortable": true},
      {"key": "time", "label": "Factories runtime (s)", "sortable": true},
      {"key": "run_time", "label": "Total runtime (s)", "sortable": true},
      {"key": "percent", "label": "% spent in factories", "sortable": true},
      {"key": "examples", "label": "Examples", "sortable": true},
      {"key": "count_per_example", "label": "Factories / example", "sortable": true}
    ],
    "items": [{"type":"uploader","count":692,"time":321.55,"run_time":401.87,"percent":80.01,"examples":789,"count_per_example":0.88},{"type":"strategy","count":70,"time":10.95,"run_time":13.98,"percent":78.29,"examples":23,"count_per_example":3.04},{"type":"replicator","count":633,"time":330.39,"run_time":439.36,"percent":75.2,"examples":951,"count_per_example":0.67},{"type":"model","count":38482,"time":10730.57,"run_time":15714.5,"percent":68.28,"examples":30377,"count_per_example":1.27},{"type":"finder","count":9528,"time":2020.16,"run_time":2984.05,"percent":67.7,"examples":3322,"count_per_example":2.87},{"type":"presenter","count":1367,"time":330.15,"run_time":489.38,"percent":67.46,"examples":1018,"count_per_example":1.34},{"type":"policy","count":5325,"time":1091.41,"run_time":1748.51,"percent":62.42,"examples":3212,"count_per_example":1.66},{"type":"worker","count":3802,"time":989.68,"run_time":1754.15,"percent":56.42,"examples":2878,"count_per_example":1.32},{"type":"serializer","count":2311,"time":624.42,"run_time":1114.73,"percent":56.02,"examples":1314,"count_per_example":1.76},{"type":"service","count":44013,"time":10688.93,"run_time":21038.68,"percent":50.81,"examples":20743,"count_per_example":2.12},{"type":"channel","count":9,"time":0.81,"run_time":1.6,"percent":50.74,"examples":11,"count_per_example":0.82},{"type":"helper","count":2260,"time":502.73,"run_time":1004.04,"percent":50.07,"examples":3522,"count_per_example":0.64},{"type":"graphql","count":4354,"time":878.21,"run_time":1755.02,"percent":50.04,"examples":3970,"count_per_example":1.1},{"type":"controller","count":15170,"time":3468.65,"run_time":6994.63,"percent":49.59,"examples":8077,"count_per_example":1.88},{"type":"mailer","count":1485,"time":275.24,"run_time":596.49,"percent":46.14,"examples":1350,"count_per_example":1.1},{"type":"request","count":50963,"time":7538.89,"run_time":16982.97,"percent":44.39,"examples":25464,"count_per_example":2.0},{"type":"view","count":1285,"time":307.48,"run_time":712.76,"percent":43.14,"examples":1198,"count_per_example":1.07},{"type":"lib","count":26973,"time":7323.0,"run_time":19383.18,"percent":37.78,"examples":35791,"count_per_example":0.75},{"type":"elastic_integration","count":91,"time":24.14,"run_time":82.95,"percent":29.1,"examples":9,"count_per_example":10.11},{"type":"experiment","count":25,"time":4.43,"run_time":15.31,"percent":28.95,"examples":74,"count_per_example":0.34},{"type":"elastic","count":80,"time":49.45,"run_time":200.27,"percent":24.69,"examples":104,"count_per_example":0.77},{"type":"routing","count":88,"time":16.93,"run_time":69.0,"percent":24.54,"examples":319,"count_per_example":0.28},{"type":"task","count":359,"time":115.95,"run_time":721.29,"percent":16.08,"examples":445,"count_per_example":0.81},{"type":"validator","count":37,"time":3.6,"run_time":26.65,"percent":13.51,"examples":178,"count_per_example":0.21},{"type":"component","count":71,"time":4.68,"run_time":38.17,"percent":12.27,"examples":305,"count_per_example":0.23},{"type":"feature","count":27713,"time":6503.11,"run_time":54689.28,"percent":11.89,"examples":10598,"count_per_example":2.61},{"type":"initializer","count":53,"time":4.75,"run_time":42.66,"percent":11.13,"examples":226,"count_per_example":0.23},{"type":"spam","count":1,"time":0.01,"run_time":0.22,"percent":4.38,"examples":1,"count_per_example":1.0},{"type":"sidekiq","count":1,"time":0.01,"run_time":0.47,"percent":2.58,"examples":1,"count_per_example":1.0},{"type":"rubocop_rspec","count":9,"time":0.08,"run_time":4.86,"percent":1.75,"examples":48,"count_per_example":0.19},{"type":"rubocop","count":108,"time":1.05,"run_time":86.95,"percent":1.2,"examples":939,"count_per_example":0.12},{"type":"support_spec","count":15,"time":0.14,"run_time":15.29,"percent":0.91,"examples":219,"count_per_example":0.07},{"type":"haml_lint","count":3,"time":0.03,"run_time":3.29,"percent":0.86,"examples":47,"count_per_example":0.06},{"type":"sidekiq_cluster","count":1,"time":0.01,"run_time":1.31,"percent":0.68,"examples":14,"count_per_example":0.07},{"type":"tooling","count":18,"time":0.17,"run_time":31.59,"percent":0.54,"examples":364,"count_per_example":0.05},{"type":"bin","count":2,"time":0.02,"run_time":14.1,"percent":0.12,"examples":43,"count_per_example":0.05},{"type":"metrics_server","count":1,"time":0.01,"run_time":12.37,"percent":0.09,"examples":37,"count_per_example":0.03},{"type":"db","count":10,"time":0.15,"run_time":197.17,"percent":0.08,"examples":3705,"count_per_example":0.0},{"type":"config","count":6,"time":0.05,"run_time":110.27,"percent":0.05,"examples":127,"count_per_example":0.05},{"type":"migration","count":255,"time":4.56,"run_time":11125.95,"percent":0.04,"examples":571,"count_per_example":0.45},{"type":"command","count":1,"time":0.01,"run_time":27.69,"percent":0.04,"examples":8,"count_per_example":0.13},{"type":"script","count":7,"time":0.06,"run_time":241.03,"percent":0.03,"examples":49,"count_per_example":0.14}],
    "filter": true
  }

How to run locally?

  1. Download data from https://gitlab.com/gitlab-org/gitlab/-/jobs/3073344776/artifacts/file/rspec/event_prof.json
  2. Run "Script" below like FORMAT=json ruby event_prof.rb event_prof.json
Script 
require 'json'

data = JSON(File.read("/home/peter/Downloads/event_prof.json"))

def time_percentage(time, total_time)
  (time / total_time * 100).round(2)
end

def ff(fl)
  fl.round(2)
end

def sum_by(key, set)
  time = set.sum { |_, e| e.dig(key, 'time') }
  run_time = set.sum { |_, e| e.dig(key, 'run_time') }
  count = set.sum { |_, e| e.dig(key, 'count') }

  {
    time: time,
    run_time: run_time,
    count: count,
    percent: time_percentage(time, run_time)
  }
end

by_type = data.group_by { |k, v| v["type"] }

factory_create = by_type.to_h { |type, set| [type, sum_by('factory.create', set)] }

case ENV['FORMAT']
when 'json'
  items = factory_create.sort_by { |_, v| -v[:percent] }.map do |type, v|
    {
      type: type,
      count: v[:count],
      time: ff(v[:time]),
      run_time: ff(v[:run_time]),
      percent: v[:percent]
    }
  end

  puts <<~MD
    ```json:table
      {
        "fields": [
          {"key": "type", "label": "Type", "sortable": true},
          {"key": "count", "label": "Factories created", "sortable": true},
          {"key": "time", "label": "Factories runtime (s)", "sortable": true},
          {"key": "run_time", "label": "Total runtime (s)", "sortable": true},
          {"key": "percent", "label": "% spent in factories", "sortable": true}
        ],
        "items": #{JSON.generate(items)},
        "filter": true
      }
    ```
  MD
else
  puts <<~MD
    | Type | Factories created | Factories runtime (s) | Total runtime (s) | Percent spent in factories |
    | -------- | ---------: | -----------------: | -------------: | -------: |
  MD

  factory_create.sort_by { |_, v| -v[:percent] }.each do |type, v|
    puts <<~MD
      | #{type} | #{v[:count]} | #{ff v[:time]} | #{ff v[:run_time]} | #{v[:percent]} |
    MD
  end
end
Edited by Peter Leitzen

Merge request reports