Skip to content

Measurable module: log all GC stats to stdout

Matthias Käppler requested to merge 209781-log-all-gc-stats into master

What does this MR do?

Closes #209781 (closed)

I briefly considered to make this a more forward-looking change by a) logging JSON to a separate file for further processing and b) pushing this logic down from the rake task to the actual services so that we can also log these outputs from API initiated exports, but discarded them in favor of this MVC which just prints it to stdout as we do currently, but instead prints all stats instead of just GC counts.

After all, the main switch currently only works for CLI-initiated imports/exports anyway so currently there is really no reason to make this more complicated than this.

I use a JSON printer so at least it's easy enough to take the output and copy it elsewhere for further processing if necessary.

Output

I, [2020-03-31T14:43:15.769963 #169]  INFO -- : Importing GitLab export: /gck/i@work/test_export.tar.gz into GitLab root/test-import as Administrator
I, [2020-03-31T14:43:15.770036 #169]  INFO -- : Measuring enabled...
I, [2020-03-31T14:43:27.088738 #169]  INFO -- : Time to finish: 00:00:11:038
I, [2020-03-31T14:43:27.088878 #169]  INFO -- : Number of sql calls: 1762
I, [2020-03-31T14:43:27.088978 #169]  INFO -- : GC stats:
I, [2020-03-31T14:43:27.089186 #169]  INFO -- : {
  "count": {
    "before": 61,
    "after": 69,
    "diff": 8
  },
  "heap_allocated_pages": {
    "before": 3893,
    "after": 5369,
    "diff": 1476
  },
  "heap_sorted_length": {
    "before": 5369,
    "after": 5369,
    "diff": 0
  },
  "heap_allocatable_pages": {
    "before": 1476,
    "after": 0,
    "diff": -1476
  },
  "heap_available_slots": {
    "before": 1586791,
    "after": 2188393,
    "diff": 601602
  },
  "heap_live_slots": {
    "before": 1311824,
    "after": 2063673,
    "diff": 751849
  },
  "heap_free_slots": {
    "before": 274967,
    "after": 124720,
    "diff": -150247
  },
  "heap_final_slots": {
    "before": 0,
    "after": 0,
    "diff": 0
  },
  "heap_marked_slots": {
    "before": 1311823,
    "after": 1604639,
    "diff": 292816
  },
  "heap_eden_pages": {
    "before": 3893,
    "after": 5369,
    "diff": 1476
  },
  "heap_tomb_pages": {
    "before": 0,
    "after": 0,
    "diff": 0
  },
  "total_allocated_pages": {
    "before": 3893,
    "after": 5369,
    "diff": 1476
  },
  "total_freed_pages": {
    "before": 0,
    "after": 0,
    "diff": 0
  },
  "total_allocated_objects": {
    "before": 6400668,
    "after": 9813212,
    "diff": 3412544
  },
  "total_freed_objects": {
    "before": 5088844,
    "after": 7749539,
    "diff": 2660695
  },
  "malloc_increase_bytes": {
    "before": 469800,
    "after": 22642352,
    "diff": 22172552
  },
  "malloc_increase_bytes_limit": {
    "before": 30330547,
    "after": 32883343,
    "diff": 2552796
  },
  "minor_gc_count": {
    "before": 46,
    "after": 53,
    "diff": 7
  },
  "major_gc_count": {
    "before": 15,
    "after": 16,
    "diff": 1
  },
  "remembered_wb_unprotected_objects": {
    "before": 16146,
    "after": 20118,
    "diff": 3972
  },
  "remembered_wb_unprotected_objects_limit": {
    "before": 32292,
    "after": 36686,
    "diff": 4394
  },
  "old_objects": {
    "before": 1277231,
    "after": 1548986,
    "diff": 271755
  },
  "old_objects_limit": {
    "before": 2554462,
    "after": 2916482,
    "diff": 362020
  },
  "oldmalloc_increase_bytes": {
    "before": 469800,
    "after": 34996648,
    "diff": 34526848
  },
  "oldmalloc_increase_bytes_limit": {
    "before": 37811614,
    "after": 43612009,
    "diff": 5800395
  }
}
I, [2020-03-31T14:43:27.089531 #169]  INFO -- : Memory usage: 453.81640625 MiB
I, [2020-03-31T14:43:27.089644 #169]  INFO -- : Label: process_169
I, [2020-03-31T14:43:27.098250 #169]  INFO -- : Done!

Does this MR meet the acceptance criteria?

Conformity

Availability and Testing

Merge request reports