November 28, 2022

Hi,

I have recently finished translating _d_arraycatnTX() to a template. While cleaning up the code, I was unable to figure out why profile-gc also shows the new template hook in addition to its former output. This behaviour is consistent on all profile-gc tests in DRuntime. One example is this one, which I had to modify by adding the line with _d_arraycatnTX():


bytes allocated, allocations, type, function, file:line
            560	              3	int[] core.internal.array.concatenation._d_arraycatnTX!(int[], string, int, string, int[], int[])._d_arraycatnTX ../../src/core/internal/array/concatenation.d:42
            464	              1	immutable(char)[][int] D main src/profilegc.d:23
            160	              1	float[][] D main src/profilegc.d:18
            160	              1	int[][] D main src/profilegc.d:15
             64	              1	double[] profilegc.main src/profilegc.d:56
             48	              1	float[] D main src/profilegc.d:42
             48	              1	int[] D main src/profilegc.d:41
             32	              1	profilegc.main.C D main src/profilegc.d:12
             32	              1	void[] profilegc.main src/profilegc.d:55
             16	              1	char[] D main src/profilegc.d:34
             16	              1	char[] D main src/profilegc.d:36
             16	              1	closure profilegc.main.foo src/profilegc.d:45
             16	              1	float D main src/profilegc.d:16
             16	              1	float[] D main src/profilegc.d:17
             16	              1	int D main src/profilegc.d:13
             16	              1	int[] D main src/profilegc.d:14
             16	              1	int[] D main src/profilegc.d:22
             16	              1	int[] D main src/profilegc.d:37
             16	              1	wchar[] D main src/profilegc.d:35

My assumption is that the GC's profiling instrumentation is introduced in the semantic phase, before the new lowering, thus also taking the _d_arraycatnTX hook into account. If this is true, then the old lowering was not profiled because it took place in the glue layer, after the instrumentation had been introduced.

Regarding this, I have 3 questions that I don't know how to answer:

  1. Is my assumption above correct?
  2. Are those 560 bytes an issue that means the new lowering over-allocates 560 bytes? The value is the same regardless of platform and OS.
  3. Is it OK for the output to contain an "internal" function, such as a runtime hook?

What do you think?

Thanks,
Teo

November 29, 2022

On Monday, 28 November 2022 at 23:00:31 UTC, Teodor Dutu wrote:

>

Hi,

I have recently finished translating _d_arraycatnTX() to a template. While cleaning up the code, I was unable to figure out why profile-gc also shows the new template hook in addition to its former output. This behaviour is consistent on all profile-gc tests in DRuntime. One example is this one, which I had to modify by adding the line with _d_arraycatnTX():


bytes allocated, allocations, type, function, file:line
            560	              3	int[] core.internal.array.concatenation._d_arraycatnTX!(int[], string, int, string, int[], int[])._d_arraycatnTX ../../src/core/internal/array/concatenation.d:42
            464	              1	immutable(char)[][int] D main src/profilegc.d:23
            160	              1	float[][] D main src/profilegc.d:18
            160	              1	int[][] D main src/profilegc.d:15
             64	              1	double[] profilegc.main src/profilegc.d:56
             48	              1	float[] D main src/profilegc.d:42
             48	              1	int[] D main src/profilegc.d:41
             32	              1	profilegc.main.C D main src/profilegc.d:12
             32	              1	void[] profilegc.main src/profilegc.d:55
             16	              1	char[] D main src/profilegc.d:34
             16	              1	char[] D main src/profilegc.d:36
             16	              1	closure profilegc.main.foo src/profilegc.d:45
             16	              1	float D main src/profilegc.d:16
             16	              1	float[] D main src/profilegc.d:17
             16	              1	int D main src/profilegc.d:13
             16	              1	int[] D main src/profilegc.d:14
             16	              1	int[] D main src/profilegc.d:22
             16	              1	int[] D main src/profilegc.d:37
             16	              1	wchar[] D main src/profilegc.d:35

My assumption is that the GC's profiling instrumentation is introduced in the semantic phase, before the new lowering, thus also taking the _d_arraycatnTX hook into account. If this is true, then the old lowering was not profiled because it took place in the glue layer, after the instrumentation had been introduced.

Regarding this, I have 3 questions that I don't know how to answer:

  1. Is my assumption above correct?
  2. Are those 560 bytes an issue that means the new lowering over-allocates 560 bytes? The value is the same regardless of platform and OS.
  3. Is it OK for the output to contain an "internal" function, such as a runtime hook?

What do you think?

Thanks,
Teo

Two ways of testing your assumption:

0: The hidden step - locate params.tracegc as the flag for enabling tracing.

  1. grep for tracegc in the code.

This reveals that the answer is that some lowering is done in semantic but the nitty gritty is performed in the code underneath the frontend - a hint that this is the case is that profile=gc does not exist on ldc and I assume gdc too.

More specifically take a look at:

    /******************************************************
     * Replace call to GC allocator with call to tracing GC allocator.
     * Params:
     *      irs = to get function from
     *      e = elem to modify in place
     *      loc = to get file/line from
     */

void toTraceGC(IRState *irs, elem *e, const ref Loc loc)
{
  1. The more fun way: Delete tracegc entirely and see what breaks

If we do:

     bool obj = true;        // write object file
     bool multiobj;          // break one object file into multiple ones
     bool trace;             // insert profiling hooks
-    bool tracegc;           // instrument calls to 'new'
+    // bool tracegc;           // instrument calls to 'new'
     bool verbose;           // verbose compile
     bool vcg_ast;           // write-out codegen-ast
     bool showColumns;       // print character (column) numbers in diagnostics

then what explodes?

src/dmd/expressionsem.d(9619): Error: no property `tracegc` for type `Param`, did you mean `dmd.globals.Param.trace`?
    src/dmd/expressionsem.d(9648): Error: no property `tracegc` for type `Param`, did you mean `dmd.globals.Param.trace`?
    src/dmd/expressionsem.d(10395): Error: no property `tracegc` for type `Param`, did you mean `dmd.globals.Param.trace`?
    src/dmd/expressionsem.d(10407): Error: no property `tracegc` for type `Param`, did you mean `dmd.globals.Param.trace`?
    src/dmd/expressionsem.d(10437): Error: no property `tracegc` for type `Param`, did you mean `dmd.globals.Param.trace`?
    src/dmd/expressionsem.d(10451): Error: no property `tracegc` for type `Param`, did you mean `dmd.globals.Param.trace`?
    src/dmd/e2ir.d(352): Error: no property `tracegc` for type `const(dmd.globals.Param*)`

and there we have our list of places to start looking.

As for one of the other questions: Internal functions should be printed. When in doubt assume the users have a reason to want the info.