Improve audit events preloading logic (!44958) · Merge requests · GitLab.org / GitLab

Tan Le requested to merge audit-event-export-improvement-adam-hegyi into master Oct 13, 2020

What does this MR do?

To export audit events to CSV, the current preloading logic attempts to preload all associated user records on more than 100k of audit events. This causes heavy strain on memory and significant slow down the whole export process.

This MR is trying to address the above performance concern by delaying the preloading process to batches of 1k using EachBatch.

Relates to #266976 (closed)

Profiling

Profiling was carried out on local env with ~ 100,000 audit events (~ 15mb cap).

Total time: 218.988679 ms

Measure Mode: wall_time
Thread ID: 70146546925520
Fiber ID: 70146516227660
Total: 218.988679
Sort by: self_time

%self      total      self      wait     child     calls  name                           location
5.29     31.720    11.584     0.009    20.126  1448768   Psych::ScalarScanner#tokenize  /Users/tanle/.rubies/2.6.6/lib/ruby/2.6.0/psych/scalar_scanner.rb:32
4.89     10.705    10.705     0.000     0.000  8808793   Regexp#===
4.53     26.842     9.928     0.006    16.907  5270381  *Class#new
2.97    216.119     6.504     0.001   209.614   466096  *Array#each
2.68     58.526     5.870     0.003    52.653  1638768  *Psych::Visitors::Visitor#visit /Users/tanle/.rubies/2.6.6/lib/ruby/2.6.0/psych/visitors/visitor.rb:15
2.67     28.663     5.847     0.002    22.814    95000   Psych::Parser#parse
2.40     72.360     5.258     0.000    67.102   329975  *Array#map
2.12     10.871     4.647     0.000     6.224  1072274   ActiveModel::LazyAttributeHash#assign_default_value /Users/tanle/.gem/ruby/2.6.6/gems/activemodel-6.0.3.3/lib/active_model/attribute_set/builder.rb:107

Total allocations: 26,313,651

Measure Mode: allocations                                        
Thread ID: 70146546925520                                                                                                         
Fiber ID: 70146516227660                                         
Total: 26313651.000000                                                                                                            
Sort by: self_time                                                                                                                
                                                                 
 %self      total      self      wait     child     calls  name                           location                                
 22.25  8554540.000 5855575.000   625.000 2698340.000  5270511  *Class#new                                                        
 17.00  4474188.000 4474188.000     0.000     0.000  8808788   Regexp#===                     
  8.26  2173387.000 2173375.000     0.000    12.000   724489   String#sub                     
  6.23  3752822.000 1638768.000    39.000 2114015.000    95000   Psych::Parser#parse                                              
  3.07  806981.000 806981.000     0.000     0.000      288   PG::Result#values                    
  2.74  719812.000 719812.000     0.000     0.000  1137924   CsvBuilder#excel_sanitize      /Users/tanle/Code/gitlab/gitlab-development-kit/gitlab/lib/csv_builder.rb:115
  2.62  688347.000 688347.000     0.000     0.000   688347   Integer#to_s                   
  2.16  2564646.000 569654.000     0.000 1994992.000   284827   BatchLoader#batch              /Users/tanle/.gem/ruby/2.6.6/gems/batch-loader-1.4.0/lib/batch_loader.rb:26
  2.16  569654.000 569654.000     0.000     0.000   284827   BatchLoader#__singleton_class  /Users/tanle/.gem/ruby/2.6.6/gems/batch-loader-1.4.0/lib/batch_loader.rb:116
  2.00  7593494.000 526432.000     0.000 7067062.000   329538  *Array#map

Databases

Get the start of `created_at`

SELECT
    "audit_events"."created_at"
FROM
    "audit_events"
WHERE
    "audit_events"."created_at" <= '2020-10-15 00:00:00'
    AND "audit_events"."created_at" >= '2020-10-01 00:00:00'
ORDER BY
    "audit_events"."created_at" ASC
LIMIT 1

https://explain.depesz.com/s/lUdq

Get the stop of `created_at` of 1k batch

SELECT
    "audit_events"."created_at"
FROM
    "audit_events"
WHERE
    "audit_events"."created_at" <= '2020-10-15 00:00:00'
    AND "audit_events"."created_at" >= '2020-10-01 00:00:00'
    AND "audit_events"."created_at" >= '2020-10-08 05:13:09.577754'
ORDER BY
    "audit_events"."created_at" ASC
LIMIT 1 OFFSET 1000

https://explain.depesz.com/s/yc0r

Load events between `created_at` start and stop range

SELECT
    "audit_events".*
FROM
    "audit_events"
WHERE
    "audit_events"."created_at" <= '2020-10-15 00:00:00'
    AND "audit_events"."created_at" >= '2020-10-01 00:00:00'
    AND "audit_events"."created_at" >= '2020-10-08 05:13:09.577754'
    AND "audit_events"."created_at" < '2020-10-13 10:00:05.463357'

https://explain.depesz.com/s/2YPu

Preload associated users in batch of 1k

SELECT
    "users"."id",
    "users"."name",
    "users"."username"
FROM
    "users"
WHERE
    "users"."id" IN (29, 22, 23, 66, 1, 49, 73, 74, 54, 33)
ORDER BY
    "users"."id" ASC
LIMIT 1000

Rails log

  AuditEvent Load (1.0ms)  SELECT "audit_events"."created_at" FROM "audit_events" WHERE "audit_events"."created_at" <= '2020-10-15 00:00:00' AND "audit_events"."created_at" >= '2020-10-01 00:00:00' ORDER BY "audit_events"."created_at" ASC LIMIT $1  [["LIMIT", 1]]
  ↳ app/models/concerns/each_batch.rb:61:in `each_batch'
  AuditEvent Load (5.0ms)  SELECT "audit_events"."created_at" FROM "audit_events" WHERE "audit_events"."created_at" <= '2020-10-15 00:00:00' AND "audit_events"."created_at" >= '2020-10-01 00:00:00' AND "audit_events"."created_at" >= '2020-10-08 05:13:09.577754' ORDER BY "audit_events"."created_at" ASC LIMIT $1 OFFSET $2  [["LIMIT", 1], ["OFFSET", 1000]]
  ↳ app/models/concerns/each_batch.rb:78:in `block in each_batch'
  AuditEvent Load (1.8ms)  SELECT "audit_events".* FROM "audit_events" WHERE "audit_events"."created_at" <= '2020-10-15 00:00:00' AND "audit_events"."created_at" >= '2020-10-01 00:00:00' AND "audit_events"."created_at" >= '2020-10-08 05:13:09.577754' AND "audit_events"."created_at" < '2020-10-13 10:00:05.463357'
  ↳ ee/lib/gitlab/audit/events/preloader.rb:22:in `block in find_each'
  User Load (1.0ms)  SELECT "users"."id", "users"."name", "users"."username" FROM "users" WHERE "users"."id" IN ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10) ORDER BY "users"."id" ASC LIMIT $75  [["id", 29], ["id", 22], ["id", 23], ["id", 66], ["id", 1], ["id", 49], ["id", 73], ["id", 74], ["id", 54], ["id", 33], ["LIMIT", 1000]]
  ↳ app/models/audit_event.rb:73:in `block in lazy_author'

Does this MR meet the acceptance criteria?

Conformity

Availability and Testing

Review and add/update tests for this feature/bug. Consider all test levels. See the Test Planning Process.
Tested in all supported browsers
[-] Informed Infrastructure department of a default or new setting change, if applicable per definition of done

Security

If this MR contains changes to processing or storing of credentials or tokens, authorization and authentication methods and other items described in the security review guidelines:

[-] Label as security and @ mention @gitlab-com/gl-security/appsec
[-] The MR includes necessary changes to maintain consistency between UI, API, email, or other methods
[-] Security reports checked/validated by a reviewer from the AppSec team

Edited Oct 16, 2020 by Tan Le

Improve audit events preloading logic