[RFC][PATCH] LD_DEBUG option to measure init time

[Maria Guseva <m dot guseva at samsung dot com>]

Currently the LD_DEBUG=statistics provides the total time spent in dynamic
linker and details it with relocation and load objects time. But other
useful information may be the time spent in init and init_array routines.
It may help to analyze the bottlenecks of application startup time. 
Attached (draft) patch measures the time of each call to .init and
.init_array entries in dl-init() for every loaded dso and cumulative time of
init() call for main executable. For each init function called also its
address is printed.  
 
The output currently looks like this (run on x86-64):
     13825:     ./a.out => /home1/m.guseva/glibc/install/lib/libc.so.6:
spent 29988 cycles in .init (== 0x00000000000218c0)
     13825:     ./a.out => /home1/m.guseva/glibc/install/lib/libc.so.6:
spent 30132 cycles in .init_array[0] (== 0x0000000000021630)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libgcc_s.so.1: spent 816 cycles in
.init (== 0x0000000000002720)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libgcc_s.so.1: spent 10598 cycles in
.init_array[0] (== 0x0000000000002b40)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libgcc_s.so.1: spent 324 cycles in
.init_array[1] (== 0x0000000000002f40)
     13825:     ./a.out => /home1/m.guseva/glibc/install/lib/libm.so.6:
spent 7828 cycles in .init (== 0x0000000000005590)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libstdc++.so.6: spent 6238 cycles in
.init (== 0x000000000005ac18)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libstdc++.so.6: spent 730 cycles in
.init_array[0] (== 0x000000000005dcb0)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libstdc++.so.6: spent 59840 cycles in
.init_array[1] (== 0x000000000005d660)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libstdc++.so.6: spent 170 cycles in
.init_array[2] (== 0x000000000005d680)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libstdc++.so.6: spent 11126 cycles in
.init_array[3] (== 0x000000000005d6c0)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libstdc++.so.6: spent 1036 cycles in
.init_array[4] (== 0x000000000005d7d0)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libstdc++.so.6: spent 1070 cycles in
.init_array[5] (== 0x000000000005d890)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libstdc++.so.6: spent 5474 cycles in
.init_array[6] (== 0x000000000005d950)
     13825:     ./a.out =>
/home1/m.guseva/trunk/gcc-4.9.2/lib64/libstdc++.so.6: spent 900 cycles in
.init_array[7] (== 0x000000000005db80)
     13825:     ./a.out => /home1/m.guseva/Test/libsample.so: spent 418
cycles in .init (== 0x00000000000005f0)
     13825:     ./a.out => /home1/m.guseva/Test/libsample.so: spent 510
cycles in .init_array[0] (== 0x0000000000000750)
     13825:     ./a.out => /home1/m.guseva/Test/libsample.so: spent
3400396160 cycles in .init_array[1] (== 0x0000000000000780)
     13825:     ./a.out => /home1/m.guseva/Test/libsample.so: spent
3400263040 cycles in .init_array[2] (== 0x00000000000007d3)
     13825:     ./a.out: spent 28160 cycles in init (== 0x00000000004006e0)

Would something like this be useful in mainline Glibc? If attitude is
generally positive I can work on more polished implementation.

I'm also thinking about having such feature for platforms without HP timing
available, like arm. Some generic time measurements may be used e.g. via
clock_gettime syscall.

	 
diff --git a/csu/libc-start.c b/csu/libc-start.c
index 138418a..b2333ca 100644
--- a/csu/libc-start.c
+++ b/csu/libc-start.c
@@ -21,6 +21,7 @@
 #include <unistd.h>
 #include <ldsodefs.h>
 #include <exit-thread.h>
+#include "hp-timing.h"

 extern void __libc_init_first (int argc, char **argv, char **envp);
 #ifndef SHARED
@@ -242,7 +243,29 @@ LIBC_START_MAIN (int (*main) (int, char **, char **
MAIN_AUXVEC_DECL),
     GLRO(dl_debug_printf) ("\ninitialize program: %s\n\n", argv[0]);
 #endif
   if (init)
-    (*init) (argc, argv, __environ MAIN_AUXVEC_PARAM);
+    {
+#if defined SHARED && ! defined HP_TIMING_NONAVAIL
+      hp_timing_t init_time;
+      hp_timing_t start_time;
+      hp_timing_t end_time;
+      HP_TIMING_NOW (start_time);
+#endif
+
+      (*init) (argc, argv, __environ MAIN_AUXVEC_PARAM);
+
+#if defined SHARED && ! defined HP_TIMING_NONAVAIL
+      HP_TIMING_NOW (end_time);
+      HP_TIMING_DIFF (init_time, start_time, end_time);
+      if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_INITTIME))
+       {
+         char buf[200];
+         HP_TIMING_PRINT (buf, sizeof (buf), init_time);
+         GLRO (dl_debug_printf) ("%s: spent %s in init (== 0x%0*lx)\n",
+                                 argv[0], buf, (int) sizeof (void *) * 2,
+                                 (unsigned long int)init);
+       }
+#endif
+    }

 #ifdef SHARED
   /* Auditing checkpoint: we have a new object.  */
diff --git a/elf/dl-init.c b/elf/dl-init.c
index 598df3b..5c8976a 100644
--- a/elf/dl-init.c
+++ b/elf/dl-init.c
@@ -18,6 +18,7 @@

 #include <stddef.h>
 #include <ldsodefs.h>
+#include "hp-timing.h"


 /* Type of the initializer.  */
@@ -33,6 +34,11 @@ extern int _dl_starting_up_internal attribute_hidden;
 static void
 call_init (struct link_map *l, int argc, char **argv, char **env)
 {
+#ifndef HP_TIMING_NONAVAIL
+  hp_timing_t init_time;
+  hp_timing_t start_time;
+  hp_timing_t end_time;
+#endif
   if (l->l_init_called)
     /* This object is all done.  */
     return;
@@ -61,7 +67,27 @@ call_init (struct link_map *l, int argc, char **argv,
char **env)
      - the others in the DT_INIT_ARRAY.
   */
   if (l->l_info[DT_INIT] != NULL)
-    DL_CALL_DT_INIT(l, l->l_addr + l->l_info[DT_INIT]->d_un.d_ptr, argc,
argv, env);
+    {
+#ifndef HP_TIMING_NONAVAIL
+      HP_TIMING_NOW (start_time);
+#endif
+      DL_CALL_DT_INIT (l, l->l_addr + l->l_info[DT_INIT]->d_un.d_ptr, argc,
+                      argv, env);
+#ifndef HP_TIMING_NONAVAIL
+      HP_TIMING_NOW (end_time);
+      HP_TIMING_DIFF (init_time, start_time, end_time);
+
+      if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_INITTIME))
+       {
+         char buf[200];
+         HP_TIMING_PRINT (buf, sizeof (buf), init_time);
+         _dl_debug_printf ("%s => %s: spent %s in .init (== 0x%0*lx)\n",
+                           argv[0], DSO_FILENAME (l->l_name), buf,
+                           (int) sizeof (void *) * 2,
+                           (unsigned long
int)(l->l_info[DT_INIT]->d_un.d_ptr));
+       }
+#endif
+    }

   /* Next see whether there is an array with initialization functions.  */
   ElfW(Dyn) *init_array = l->l_info[DT_INIT_ARRAY];
@@ -75,7 +101,26 @@ call_init (struct link_map *l, int argc, char **argv,
char **env)

       addrs = (ElfW(Addr) *) (init_array->d_un.d_ptr + l->l_addr);
       for (j = 0; j < jm; ++j)
-       ((init_t) addrs[j]) (argc, argv, env);
+       {
+#ifndef HP_TIMING_NONAVAIL
+         HP_TIMING_NOW (start_time);
+#endif
+         ((init_t) addrs[j]) (argc, argv, env);
+#ifndef HP_TIMING_NONAVAIL
+         HP_TIMING_NOW (end_time);
+         HP_TIMING_DIFF (init_time, start_time, end_time);
+
+         if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_INITTIME))
+           {
+             char buf[200];
+             HP_TIMING_PRINT (buf, sizeof (buf), init_time);
+             _dl_debug_printf
+               ("%s => %s: spent %s in .init_array[%u] (== 0x%0*lx)\n",
argv[0],
+                DSO_FILENAME (l->l_name), buf, j, (int) sizeof (void *) *
2,
+                (unsigned long int)(addrs[j] - l->l_addr));
+           }
+#endif
+       }
     }
 }

diff --git a/elf/rtld.c b/elf/rtld.c
index d5cace8..95e75a7 100644
--- a/elf/rtld.c
+++ b/elf/rtld.c
@@ -2241,6 +2241,8 @@ process_dl_debug (const char *dl_debug)
        DL_DEBUG_STATISTICS },
       { LEN_AND_STR ("unused"), "determined unused DSOs",
        DL_DEBUG_UNUSED },
+      { LEN_AND_STR ("init_time"), "display init time",
+    DL_DEBUG_INITTIME },
       { LEN_AND_STR ("help"), "display this help message and exit",
        DL_DEBUG_HELP },
     };
diff --git a/sysdeps/generic/ldsodefs.h b/sysdeps/generic/ldsodefs.h
index e01df84..26e7186 100644
--- a/sysdeps/generic/ldsodefs.h
+++ b/sysdeps/generic/ldsodefs.h
@@ -452,6 +452,7 @@ struct rtld_global_ro
 /* These two are used only internally.  */
 #define DL_DEBUG_HELP       (1 << 10)
 #define DL_DEBUG_PRELINK    (1 << 11)
+#define DL_DEBUG_INITTIME   (1 << 12)

   /* OS version.  */
   EXTERN unsigned int _dl_osversion;


Regards,
Maria