Zero times in profiling with GHC-6.8.1

[daniel.is.fischer]

Profiling runs always report 0 ticks, hence the -P option only gives useful allocation stats, -hX, where X is one of b, c... always yield empty graphs.

[daniel.is.fischer]

Source code & data files, compilation and run logs

[simonmar]

Works for me:

        Tue Nov 27 13:32 2007 Time and Allocation Profiling Report  (Final)

           a.out +RTS -P -RTS MMDataA

        total time  =        6.50 secs   (325 ticks @ 20 ms)
        total alloc = 4,296,710,936 bytes  (excludes profiling overheads)

I wonder if this is some incompatibility with whatever kernel version you have? GHC is using timer_create(), a relatively new API.

Which version of Linux are you running, and where did you get your GHC binary from?

[daniel.is.fischer]

I run SuSE 8.2, kernel version is 2.4.20, so it probably hasn't timer_create() yet. I compiled my GHC from source.

[simonmar]

I also have a 2.4.20 system here, and I can't reproduce your bug on it. This is RedHat? 9, which might have different kernel patches to your SuSE system though.

Is USE_TIMER_CREATE set in mk/config.h in your GHC build? On my 2.4.20 system it is turned off, because the configure test failed.

[daniel.is.fischer]

It is set:

/* Define to 1 if you have the `timer_create' function. */
#define HAVE_TIMER_CREATE 1

/* Define to 1 if we can use timer_create(CLOCK_PROCESS_CPUTIME_ID,...) */
#define USE_TIMER_CREATE 1

[simonmar]

Then you could try commenting out the #define USE_TIMER_CREATE 1 line in includes/ghcautoconf.h, and recompiling the rts. If that works, we need to figure out what went wrong with the configure test.

[daniel.is.fischer]

Sorry for the stupid question, but how do I recompile the rts? I'm not keen on rebuilding the complete thing, so would I just cd rts; make; cd .. ; make install ? Or would I need to take other steps?

[simonmar]

Yes, that should work. Or you can skip the make install step and run GHC directly from the build tree, by running compiler/stage2/ghc-inplace.

[daniel.is.fischer]

Indeed, that did work. Would the config.log help in figuring out what went wrong?

dafis@linux:~/EulerProblems/SubteamA/MasterMind> ~/Haskell/RecentHZips/ghc-6.8.1/compiler/stage2/ghc-inplace -O2 -prof -auto-all -osuf pr_o -hisuf pr_hi -o rMaster --make master
[1 of 1] Compiling Main             ( master.hs, master.pr_o )
Linking rMaster ...
dafis@linux:~/EulerProblems/SubteamA/MasterMind> ./rMaster +RTS -P -sstderr -RTS MMDataA
./rMaster MMDataA +RTS -P -sstderr
4816567204758932
2,018,820,728 bytes allocated in the heap
 69,460,240 bytes copied during GC (scavenged)
      7,168 bytes copied during GC (not scavenged)
    139,264 bytes maximum residency (14 sample(s))

       3851 collections in generation 0 (  1.45s)
         14 collections in generation 1 (  0.02s)

          2 Mb total memory in use

  INIT  time    0.00s  (  0.00s elapsed)
  MUT   time   16.73s  ( 23.02s elapsed)
  GC    time    1.47s  (  2.26s elapsed)
  RP    time    0.00s  (  0.00s elapsed)
  PROF  time    0.00s  (  0.00s elapsed)
  EXIT  time    0.00s  (  0.00s elapsed)
  Total time   18.20s  ( 25.28s elapsed)

  %GC time       8.1%  (8.9% elapsed)

  Alloc rate    120,670,695 bytes per MUT second

  Productivity  91.9% of total user, 66.2% of total elapsed

And rMaster.prof:

	Wed Nov 28 16:46 2007 Time and Allocation Profiling Report  (Final)

	   rMaster +RTS -P -sstderr -RTS MMDataA

	total time  =       16.96 secs   (848 ticks @ 20 ms)
	total alloc = 1,313,421,616 bytes  (excludes profiling overheads)

COST CENTRE                    MODULE               %time %alloc  ticks     bytes

appCon                         Main                  50.4   70.3    427 230850097
steps                          Main                  23.2    9.8    197  32234523
unchosen                       Main                  14.0    9.2    119  30046098
full                           Main                   7.1   10.0     60  32779939
forbid                         Main                   2.0    0.0     17         0
choose                         Main                   1.5    0.6     13   2132353


                                                                                               individual    inherited
COST CENTRE              MODULE                                               no.    entries  %time %alloc   %time %alloc  ticks     bytes

MAIN                     MAIN                                                   1           0   0.0    0.0   100.0  100.0      0       152
 main                    Main                                                 188           1   0.0    0.0   100.0  100.0      0       244
  fromFile               Main                                                 189           2   0.0    0.0   100.0  100.0      0     52652
   out                   Main                                                 212           1   0.0    0.0     0.0    0.0      0      9704
   noInfo                Main                                                 207           1   0.0    0.0     0.0    0.0      0       972
   untie                 Main                                                 206           1   0.0    0.0     0.0    0.0      0      2084
   full                  Main                                                 194       83340   7.1   10.0   100.0  100.0     60 131119756
    con2tag_Isit#        Main                                                 203       28824   0.0    0.0     0.0    0.0      0         0
    steps                Main                                                 195      295637  23.2    9.8    92.9   90.0    197 128937404
     selected            Main                                                 210          16   0.0    0.0     0.0    0.0      0       192
     unselected          Main                                                 209         256   0.0    0.0     0.0    0.0      0      9216
     appPoss             Main                                                 208          17   0.0    0.0     0.0    0.0      0     45424
     chosen              Main                                                 204      138902   0.6    0.0     1.5    0.1      5         0
      mustBe             Main                                                 205     1156314   0.9    0.1     0.9    0.1      8    971272
     unchosen            Main                                                 200    10015366  14.0    9.2    16.0    9.2    119 120184392
      forbid             Main                                                 201     1815159   2.0    0.0     2.0    0.0     17         0
     appCon              Main                                                 197      698230  50.4   70.3    50.6   70.3    427 923399700
      binom              Main                                                 202      644946   0.2    0.0     0.2    0.0      2         0
     choose              Main                                                 196      464897   1.5    0.6     1.5    0.6     13   8529412
   con2tag_Isit#         Main                                                 193          48   0.0    0.0     0.0    0.0      0         0
   line2Con              Main                                                 190          17   0.0    0.0     0.0    0.0      0    107616
    binom                Main                                                 191          17   0.0    0.0     0.0    0.0      0         0
 CAF                     Main                                                 182          12   0.0    0.0     0.0    0.0      0        96
  noInfo                 Main                                                 211           0   0.0    0.0     0.0    0.0      0       408
  appCon                 Main                                                 199           0   0.0    0.0     0.0    0.0      0       688
  steps                  Main                                                 198           0   0.0    0.0     0.0    0.0      0       688
  binom                  Main                                                 192           0   0.0    0.0     0.0    0.0      0     37812
 CAF                     Text.Read.Lex                                        159           8   0.0    0.0     0.0    0.0      0      1772
 CAF                     GHC.Read                                             154           1   0.0    0.0     0.0    0.0      0       976
 CAF                     GHC.Int                                              148           1   0.0    0.0     0.0    0.0      0       108
 CAF                     Foreign.Storable                                     145           1   0.0    0.0     0.0    0.0      0        44
 CAF                     GHC.Handle                                           134           7   0.0    0.0     0.0    0.0      0      8720
 CAF                     System.Posix.Internals                               118           7   0.0    0.0     0.0    0.0      0       112

[simonmar]

Yes, please attach your config.log.

[simonmar]

Please try the attached patch to aclocal.m4. Apply the patch, then autoconf; ./configure.

[daniel.is.fischer]

patch applied manually because

dafis@linux:~/Haskell/RecentHZips/ghc-6.8.1> patch -b aclocal.m4 timer-create.patch
?
patch: **** ed FAILED

then autoconf; ./configure, last lines of that are

checking for timer_settime... yes
checking for a working timer_create()... yes
checking for printf$LDBLStub... no
checking for pkg-config... /usr/bin/pkg-config
checking for PAPI_library_init in -lpapi... no
checking papi.h usability... no
checking papi.h presence... no
checking for papi.h... no
configure: creating ./config.status
config.status: creating mk/config.mk
config.status: creating ghc.spec
config.status: creating extra-gcc-opts
config.status: creating docs/users_guide/ug-book.xml
config.status: creating mk/config.h
config.status: mk/config.h is unchanged
config.status: executing mk/stamp-h commands
dafis@linux:~/Haskell/RecentHZips/ghc-6.8.1>

and HAVE_TIMER_CREATE and USE_TIMER_CREATE are indeed still defined as 1, the line #define USE_TIMER_CREATE 1 in includes/ghcautoconf.h is still commented out.

[simonmar]

(the patch was a darcs patch, sorry for not mentioning that)

Ok, could you possibly investigate this manually? It's pretty hard to debug it remotely. To experiment, you can just cut out the test program from aclocal.m4 and play with it separately.

Clearly something is not working with timer_create() on your system, we need to figure out what it is, and write a configure test that detects the problem. One thing you could try is modifying the test to test the CLOCK_PROCESS_CPUTIME_ID timer instead of the CLOCK_REALTIME timer, but you'll need to add a cpu-time-consuming loop into the code.

[daniel.is.fischer]

I don't really know what I'm doing, but after digging in a number of header files I did not understand, I got this programme:

#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <signal.h>
#include <unistd.h>
static volatile int tock = 0;
static void handler(int i)
{
   tock = 1;
}

int main(int argc, char *argv[])
{

    struct sigevent ev;
    timer_t timer;
    struct itimerspec it;
    struct sigaction action;
    unsigned int i;
    int m,n,count = 0;

    ev.sigev_notify = SIGEV_SIGNAL;
    ev.sigev_signo  = SIGVTALRM;
    printf("%u\n",i);
    printf("Random timer is %d\n",timer);
    printf("Getting time\n");
    m = timer_gettime(timer,&it);
    printf("Resulted in %d\n",m);
    printf("Timer says: interval is %lld, %ld,\nvalue is %lld, %ld\n"
            ,(long long)it.it_interval.tv_sec,it.it_interval.tv_nsec
            ,(long long)it.it_value.tv_sec,it.it_value.tv_nsec);
    printf("timer is %d after first gettime\n",timer);
    if (timer_create(CLOCK_PROCESS_CPUTIME_ID, &ev, &timer) != 0) {
        printf("No CLOCK_PROCESS_CPUTIME_ID timer\n");
       exit(1);
    }
    printf("timer created with CLOCK_PROCESS_CPUTIME_ID is %d\n",timer);
    for(n = 3; n < 20000; n++){
        for(m = 2; m <= n/2; m++){
            if (!(n%m)) count++;
        }
    }
    printf("%d divisors\n",count);
    printf("Getting time\n");
    m = timer_gettime(timer,&it);
    printf("Resulted in %d\n",m);
    printf("Timer says: interval is %lld, %ld,\nvalue is %lld, %ld\n"
            ,(long long)it.it_interval.tv_sec,it.it_interval.tv_nsec
            ,(long long)it.it_value.tv_sec,it.it_value.tv_nsec);
    printf("timer now is %d\n",timer);
    if (timer_create(CLOCK_REALTIME, &ev, &timer) != 0) {
        printf("No CLOCK_REALTIME timer\n");
       exit(2);
    }
    printf("timer created with CLOCK_REALTIME is %d\n",timer);
    printf("Getting time\n");
    m = timer_gettime(timer,&it);
    printf("Resulted in %d\n",m);
    printf("Timer says: interval is %lld, %ld,\nvalue is %lld, %ld\n"
            ,(long long)it.it_interval.tv_sec,it.it_interval.tv_nsec
            ,(long long)it.it_value.tv_sec,it.it_value.tv_nsec);
    printf("timer now is %d\n",timer);
    for(n = 3; n < 20000; n++){
        for(m = 2; m <= n/2; m++){
            if (!(n%m)) count++;
        }
    }
    printf("%d divisors\n",count);
    printf("Getting time\n");
    m = timer_gettime(timer,&it);
    printf("Resulted in %d\n",m);
    printf("Timer says: interval is %lld, %ld,\nvalue is %lld, %ld\n"
            ,(long long)it.it_interval.tv_sec,it.it_interval.tv_nsec
            ,(long long)it.it_value.tv_sec,it.it_value.tv_nsec);
    printf("timer finally is %d\n",timer);

    action.sa_handler = handler;
    action.sa_flags = 0;
    sigemptyset(&action.sa_mask);
    if (sigaction(SIGVTALRM, &action, NULL) == -1) {
        printf("SIGVTALRM problem\n");
        exit(3);
    }

    it.it_value.tv_sec = 0;
    it.it_value.tv_nsec = 1;
    it.it_interval = it.it_value;
    if (timer_settime(timer, 0, &it, NULL) != 0) {
        printf("settime problem\n");
        exit(4);
    }

    usleep(100);
    if (tock) exit(0);
    exit(5);
    return 0;
    exit(0);
}  

and from that the output

dafis@linux:~/Documents> gcc -Wall -o timerTest Timertest.c -lrt
dafis@linux:~/Documents> ./timerTest
134513370
Random timer is 1075293183
Getting time
Resulted in -1
Timer says: interval is 1075248004, -1073745532,
value is 1074079461, 1075321808
timer is 1075293183 after first gettime
timer created with CLOCK_PROCESS_CPUTIME_ID is 0
161150 divisors
Getting time
Resulted in 0
Timer says: interval is 0, 0,
value is 0, 0
timer now is 0
timer created with CLOCK_REALTIME is 1
Getting time
Resulted in 0
Timer says: interval is 0, 0,
value is 0, 0
timer now is 1
322300 divisors
Getting time
Resulted in 0
Timer says: interval is 0, 0,
value is 0, 0
timer finally is 1
dafis@linux:~/Documents>

So if I interpret this right, timer_create does work, but timer_gettime doesn't.

If you give me a good lead, I can investigate further, but I know practically nothing about the C-libs, so please be detailed.

[simonmar]

Daniel: could you try this modified version of your test program and let me know the results?

#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <signal.h>
#include <unistd.h>
static volatile int tock = 0;
static void handler(int i)
{
   tock = 1;
}

int main(int argc, char *argv[])
{

    struct sigevent ev;
    timer_t timer;
    struct itimerspec it;
    struct sigaction action;
    int m,n,count = 0;

    ev.sigev_notify = SIGEV_SIGNAL;
    ev.sigev_signo  = SIGVTALRM;

    action.sa_handler = handler;
    action.sa_flags = 0;
    sigemptyset(&action.sa_mask);
    if (sigaction(SIGVTALRM, &action, NULL) == -1) {
        printf("SIGVTALRM problem\n");
        exit(3);
    }

    if (timer_create(CLOCK_PROCESS_CPUTIME_ID, &ev, &timer) != 0) {
        printf("No CLOCK_PROCESS_CPUTIME_ID timer\n");
       exit(1);
    }

    it.it_value.tv_sec = 0;
    it.it_value.tv_nsec = 1;
    it.it_interval = it.it_value;
    if (timer_settime(timer, 0, &it, NULL) != 0) {
        printf("settime problem\n");
        exit(4);
    }

    tock = 0;

    for(n = 3; n < 20000; n++){
        for(m = 2; m <= n/2; m++){
            if (!(n%m)) count++;
            if (tock) goto out;
        }
    }
out:

    if (!tock) {
        printf("no CLOCK_REALTIME signal\n");
        exit(5);
    }

    timer_delete(timer);

    if (timer_create(CLOCK_REALTIME, &ev, &timer) != 0) {
        printf("No CLOCK_REALTIME timer\n");
        exit(2);
    }

    it.it_value.tv_sec = 0;
    it.it_value.tv_nsec = 1;
    it.it_interval = it.it_value;
    if (timer_settime(timer, 0, &it, NULL) != 0) {
        printf("settime problem\n");
        exit(4);
    }

    tock = 0;

    usleep(100);

    if (!tock) {
        printf("no CLOCK_REALTIME signal\n");
        exit(5);
    }

    timer_delete(timer);

    exit(0);
}  

[daniel.is.fischer]

That says: no CLOCK_REALTIME signal.

[simonmar]

Ok, I've added that as the autoconf test, so hopefully it should detect that your system has a non-working timer_create(). I don't understand why the earlier patch didn't work, but still.

To merge:

ue Apr 29 14:29:45 PDT 2008  Simon Marlow <simonmar@microsoft.com>
  * FIX #1933: use a better test for timer_create()

Also Igloo: just as a sanity check could you make sure that after this patch configure is still detecting a working timer_create() on your systems?

[igloo]

Merged, and looks good:

checking for timer_create... yes
checking for timer_settime... yes
checking for a working timer_create(CLOCK_REALTIME)... yes