www.digitalmars.com         C & C++   DMDScript  

digitalmars.D - GC profiling upon exit()

reply =?UTF-8?Q?Ali_=c3=87ehreli?= <acehreli yahoo.com> writes:
I've noticed that GC profiling[1] is not provided if the application 
exit()s as opposed to returns. Is that intended? Would it be possible to 
print it still?

Related, stdout may not be the best place for that information: ;)

   https://issues.dlang.org/show_bug.cgi?id=15602

Ali

[1] https://dlang.org/spec/garbage.html#gc_config
Aug 11 2016
parent reply Jonathan M Davis via Digitalmars-d <digitalmars-d puremagic.com> writes:
On Thursday, August 11, 2016 02:17:06 Ali Çehreli via Digitalmars-d wrote:

 I've noticed that GC profiling[1] is not provided if the application
 exit()s as opposed to returns. Is that intended? Would it be possible to
 print it still?

 Related, stdout may not be the best place for that information: ;)

    https://issues.dlang.org/show_bug.cgi?id=15602

 Ali

 [1] https://dlang.org/spec/garbage.html#gc_config


Well, you could register stuff with atexit() so that it runs when exit() is
called, but calling exit() isn't much better than hitting assert(0) or using
ctrl-c. exit() doesn't shut things down even vaguely cleanly. So, you
_might_ be able to get something thanks to atexit(), but I'm not sure how
much you can really do given that your program has basically just been shot
in the head.

- Jonathan M Davis
Aug 11 2016
parent reply =?UTF-8?Q?Ali_=c3=87ehreli?= <acehreli yahoo.com> writes:
On 08/11/2016 02:56 AM, Jonathan M Davis via Digitalmars-d wrote:

 On Thursday, August 11, 2016 02:17:06 Ali Çehreli via Digitalmars-d 


wrote:

 I've noticed that GC profiling[1] is not provided if the application
 exit()s as opposed to returns. Is that intended? Would it be possible to
 print it still?

 Related, stdout may not be the best place for that information: ;)

    https://issues.dlang.org/show_bug.cgi?id=15602

 Ali

 [1] https://dlang.org/spec/garbage.html#gc_config


 Well, you could register stuff with atexit() so that it runs when 


exit() is

 called, but calling exit() isn't much better than hitting assert(0) 


or using

 ctrl-c. exit() doesn't shut things down even vaguely cleanly.


Agreed that assert(0) is fatal but Ctrl-C is just a signal that can be 
handled cleanly. exit() is not necessarily an error return. It just 
means that the application does not care about regular cleanup.


 So, you
 _might_ be able to get something thanks to atexit(), but I'm not sure how
 much you can really do given that your program has basically just 


been shot

 in the head.


The good thing is that the application may be calling exit() itself, 
where it could have made a call to get the profile information. The main 
issue here is that the output of GC profile information is hardwired to 
GC destruction (and stdout).

I've opened this enhancement request:

   https://issues.dlang.org/show_bug.cgi?id=16377

Ali
Aug 11 2016
parent =?UTF-8?Q?Ali_=c3=87ehreli?= <acehreli yahoo.com> writes:
On 08/11/2016 02:34 PM, Ali Çehreli wrote:


 the application may be calling exit() itself,
 where it could have made a call to get the profile information. The main
 issue here is that the output of GC profile information is hardwired to
 GC destruction (and stdout).


Instead of coming up with a design and fixing druntime, for now I hacked 
it by

1) Declaring druntime's profiling variables with their mangled names

2) Copying and modifying the druntime code that dumps stats so that it 
accepts any FILE*

Sorry to dump this code here but maybe others will need it as well. The 
program must be started by turning GC profiling on:

   $ ./foo "--DRT-gcopt=profile:1"

(See https://dlang.org/spec/garbage.html#gc_config )

Ali

/* HACK: A helper mixin that converts pairs of types and symbols to 
their corresponding declarations accessible from
    druntime. For example, the following definition is produced for the 
pair of (int, "i"):

    extern(C) pragma(mangle, mangle!int("gc.gc.i")) extern __gshared int i;
*/
mixin template declareGCProfVars(A...) {
     string definitions() {
         string result;
         string currentType;

         /* static */ foreach(i, a; A) {
             static if ((i % 2) == 0) {
                 static assert(is(a), "Expected a type, not " ~ a.stringof);
                 currentType = a.stringof;    // Save for the next iteration
             }
             else {
                 static assert (is(typeof(a) == string), "Expected 
string, not " ~ a.stringof);
                 result ~= `extern(C) pragma(mangle, mangle!` ~ 
currentType ~ `("gc.gc.`
                           ~ a ~ `")) extern __gshared ` ~ currentType ~ 
` ` ~ a ~ `;`;
                 currentType = "";    // play safe
             }
         }
         return result;
     }

     import core.demangle;
     mixin (definitions());
}

/* List of GC profiling variables that druntime uses as of 2.071. Copied 
from src/gc/impl/conservative/gc.d of
  * https://github.com/dlang/druntime */
import std.datetime : Duration;
mixin declareGCProfVars!(
     Duration, "prepTime",
     Duration, "markTime",
     Duration, "sweepTime",
     Duration, "recoverTime",
     Duration, "maxPauseTime",
     size_t, "numCollections",
     size_t, "maxPoolMemory",
);

public import std.stdio : FILE;

void dumpGCProfile(FILE *file) {
     import std.stdio : fprintf;

     /* Adapted from src/gc/impl/conservative/gc.d of 
https://github.com/dlang/druntime */

     fprintf(file, "\tNumber of collections:  %llu\n", 
cast(ulong)numCollections);
     fprintf(file, "\tTotal GC prep time:  %lld milliseconds\n",
             prepTime.total!("msecs"));
     fprintf(file, "\tTotal mark time:  %lld milliseconds\n",
             markTime.total!("msecs"));
     fprintf(file, "\tTotal sweep time:  %lld milliseconds\n",
             sweepTime.total!("msecs"));
     fprintf(file, "\tTotal page recovery time:  %lld milliseconds\n",
             recoverTime.total!("msecs"));
     const long maxPause = maxPauseTime.total!("msecs");
     fprintf(file, "\tMax Pause Time:  %lld milliseconds\n", maxPause);
     const long gcTime = (recoverTime + sweepTime + markTime + 
prepTime).total!("msecs");
     fprintf(file, "\tGrand total GC time:  %lld milliseconds\n", gcTime);
     const long pauseTime = (markTime + prepTime).total!("msecs");

     fprintf(file, "GC summary:%5lld MB,%5lld GC%5lld ms, Pauses%5lld ms 
<%5lld ms\n",
             cast(long) maxPoolMemory >> 20, cast(ulong)numCollections, 
gcTime,
             pauseTime, maxPause);
}

bool isGCProfOn() {
     import core.runtime : Runtime;
     import std.regex : ctRegex, match;
     import std.algorithm : any;

     /* Although the GC documentation says that the program arguments 
"are still available via rt_args"[1], they seem to
      * be available only through Runtime.args().
      *
      * [1] https://dlang.org/spec/garbage.html#gc_config
      */
     enum r = ctRegex!"--DRT-gcopt.*profile:1";
     return Runtime.args().any!(arg => arg.match(r));
}

import std.range;
import std.algorithm;
import std.stdio;
import core.stdc.stdlib;

void main() {
     // Cause some allocations
     size_t total;
     iota(1000).each!(i => total += iota(1000).map!(j => new 
int[10000]).array.length);
     writeln(total);

     /* Let's assume that the program is about to exit() but we're still 
interested in GC stats. First ensure that the
      * stats are requested on the command line. */
     if (isGCProfOn()) {
         dumpGCProfile(stderr.getFP());
     }

     exit(0);
}
Aug 11 2016