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

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

>  Can you please test on one non-HP platform to show it still compiles and
you didn't make any mistakes there?
Tested on arm.

> I agree that two distinct patches are a good idea. However, I want to set
the expectation that for a complete implementation you must support both. I
do not consider this a complete solution until both HP > and non-HP timings
are supported, either via a generic solution for HP or another interface.
Ok, I'll submit another patch in separate thread.

>> +#if defined SHARED && ! defined HP_TIMING_NONAVAIL
> Should use `HP_TIMING_NONAVAIL', never `defined HP_TIMING_NONAVAIL' since
all macros should always be defined to a value of 0 or 1.
Fixed this plus fixed some warnings during build. Updated patch is below.

2015-08-05  Maria Guseva  <m.guseva@samsung.com>

	* csu/libc-start.c: Include hp-timing.h
	(LIBC_START_MAIN): Add timing and print for DL_DEBUG_CTORDTOR_TIME.
	* elf/Makefile (test-srcs): Add tst-ctordtor_time.
	(tests-special): Add tst-ctordtor_time.
	(tst-ctordtor_time.out): Add rule for new test.
	* elf/dl-fini.c: Include hp-timing.h
	(_dl_fini): Add timing and print for DL_DEBUG_CTORDTOR_TIME.
	* elf/dl-init.c: Include hp-timing.h
	(call_init): Add timing and print for DL_DEBUG_CTORDTOR_TIME.
	* elf/rtld.c (debopts): Changed len of struct fields name and
helptext,
	add element for DL_DEBUG_CTORDTOR_TIME
	(process_dl_debug): Fix print for new DL_DEBUG_CTORDTOR_TIME element
	* elf/tst-ctordtor_time.c: New test for LD_DEBUG=ctordtor_time
	* elf/tst-ctordtor_time.sh: New test for LD_DEBUG=ctordtor_time
	* sysdeps/generic/ldsodefs.h (DL_DEBUG_CTORDTOR_TIME): New define.


 csu/libc-start.c           |   24 +++++++++++++++++++
 elf/Makefile               |    9 +++++--
 elf/dl-fini.c              |   55
+++++++++++++++++++++++++++++++++++++++++++
 elf/dl-init.c              |   48 +++++++++++++++++++++++++++++++++++++
 elf/rtld.c                 |   12 +++++++---
 elf/tst-ctordtor_time.c    |   41 ++++++++++++++++++++++++++++++++
 elf/tst-ctordtor_time.sh   |   56
++++++++++++++++++++++++++++++++++++++++++++
 sysdeps/generic/ldsodefs.h |    1 +
 9 files changed, 259 insertions(+), 5 deletions(-)
 create mode 100644 elf/tst-ctordtor_time.c
 create mode 100644 elf/tst-ctordtor_time.sh

diff --git a/csu/libc-start.c b/csu/libc-start.c
index 0afa7c0..266de7c 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,8 +243,31 @@ 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)
+    {
+#if defined SHARED && HP_TIMING_AVAIL
+      hp_timing_t init_time;
+      hp_timing_t start_time;
+      hp_timing_t end_time;
+      if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME))
+	HP_TIMING_NOW (start_time);
+#endif
+
     (*init) (argc, argv, __environ MAIN_AUXVEC_PARAM);
 
+#if defined SHARED && HP_TIMING_AVAIL
+      if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME))
+	{
+	  HP_TIMING_NOW (end_time);
+	  HP_TIMING_DIFF (init_time, start_time, end_time);
+	  char buf[200];
+	  HP_TIMING_PRINT (buf, sizeof (buf), init_time);
+	  GLRO (dl_debug_printf) ("%s => %s: spent %s in init (==
0x%0*lx)\n",
+				  argv[0], argv[0], buf, (int) sizeof (void
*) * 2,
+				  (unsigned long int) init);
+	}
+#endif
+
+    }
 #ifdef SHARED
   /* Auditing checkpoint: we have a new object.  */
   if (__glibc_unlikely (GLRO(dl_naudit) > 0))
diff --git a/elf/Makefile b/elf/Makefile
index 4ceeaf8..61a313b 100644
--- a/elf/Makefile
+++ b/elf/Makefile
@@ -154,7 +154,7 @@ ifeq ($(build-hardcoded-path-in-tests),yes)
 tests += tst-dlopen-aout
 LDFLAGS-tst-dlopen-aout = $(no-pie-ldflag)
 endif
-test-srcs = tst-pathopt
+test-srcs = tst-pathopt tst-ctordtor_time
 selinux-enabled := $(shell cat /selinux/enforce 2> /dev/null)
 ifneq ($(selinux-enabled),1)
 tests-execstack-yes = tst-execstack tst-execstack-needed tst-execstack-prog
@@ -285,7 +285,7 @@ tests-special += $(objpfx)order-cmp.out
$(objpfx)tst-array1-cmp.out \
 		 $(objpfx)tst-array5-static-cmp.out $(objpfx)order2-cmp.out
\
 		 $(objpfx)tst-initorder-cmp.out \
 		 $(objpfx)tst-initorder2-cmp.out $(objpfx)tst-unused-dep.out
\
-		 $(objpfx)tst-unused-dep-cmp.out
+		 $(objpfx)tst-unused-dep-cmp.out
$(objpfx)tst-ctordtor_time.out
 endif
 
 check-abi: $(objpfx)check-abi-ld.out
@@ -1205,3 +1205,8 @@ $(objpfx)tst-unused-dep.out: $(objpfx)testobj1.so
 $(objpfx)tst-unused-dep-cmp.out: $(objpfx)tst-unused-dep.out
 	cmp $< /dev/null > $@; \
 	$(evaluate-test)
+
+$(objpfx)tst-ctordtor_time.out: tst-ctordtor_time.sh
$(objpfx)tst-ctordtor_time
+	    $(SHELL) $< $(common-objpfx) '$(test-program-prefix-before-env)'
\
+	    '$(run-program-env)' '$(test-program-prefix-after-env)'; \
+        $(evaluate-test)
diff --git a/elf/dl-fini.c b/elf/dl-fini.c
index 6cfe651..4254b98 100644
--- a/elf/dl-fini.c
+++ b/elf/dl-fini.c
@@ -20,6 +20,7 @@
 #include <assert.h>
 #include <string.h>
 #include <ldsodefs.h>
+#include "hp-timing.h"
 
 
 /* Type of the constructor functions.  */
@@ -142,6 +143,11 @@ _dl_fini (void)
      determining the order of the modules once again from the beginning.
*/
   struct link_map **maps = NULL;
   size_t maps_size = 0;
+#if HP_TIMING_AVAIL
+  hp_timing_t fini_time;
+  hp_timing_t start_time = 0;
+  hp_timing_t end_time;
+#endif
 
   /* We run the destructors of the main namespaces last.  As for the
      other namespaces, we pick run the destructors in them in reverse
@@ -249,12 +255,61 @@ _dl_fini (void)
 		      unsigned int i =
(l->l_info[DT_FINI_ARRAYSZ]->d_un.d_val
 					/ sizeof (ElfW(Addr)));
 		      while (i-- > 0)
+			{
+#if HP_TIMING_AVAIL
+			  if (__glibc_unlikely
+			      (GLRO (dl_debug_mask) &
DL_DEBUG_CTORDTOR_TIME))
+			    HP_TIMING_NOW (start_time);
+#endif
 			((fini_t) array[i]) ();
+#if HP_TIMING_AVAIL
+			  if (__glibc_unlikely
+			      (GLRO (dl_debug_mask) &
DL_DEBUG_CTORDTOR_TIME))
+			    {
+			      HP_TIMING_NOW (end_time);
+			      HP_TIMING_DIFF (fini_time, start_time,
+					      end_time);
+			      char buf[200];
+			      HP_TIMING_PRINT (buf, sizeof (buf),
fini_time);
+			      _dl_debug_printf
+				("%s => %s: spent %s in .fini_array[%u] (==
0x%0*lx)\n",
+				 DSO_FILENAME (maps[0]->l_name),
+				 DSO_FILENAME (l->l_name), buf, i,
+				 (int) sizeof (void *) * 2,
+				 (unsigned long int) ((fini_t) array[i] -
+						      l->l_addr));
+			    }
+#endif
+			}
 		    }
 
 		  /* Next try the old-style destructor.  */
 		  if (l->l_info[DT_FINI] != NULL)
+		    {
+#if HP_TIMING_AVAIL
+		      if (__glibc_unlikely
+			  (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME))
+			HP_TIMING_NOW (start_time);
+#endif
 		     DL_CALL_DT_FINI(l, l->l_addr +
l->l_info[DT_FINI]->d_un.d_ptr);
+#if HP_TIMING_AVAIL
+		      if (__glibc_unlikely
+			  (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME))
+			{
+			  HP_TIMING_NOW (end_time);
+			  HP_TIMING_DIFF (fini_time, start_time, end_time);
+			  char buf[200];
+			  HP_TIMING_PRINT (buf, sizeof (buf), fini_time);
+			  _dl_debug_printf
+			    ("%s => %s: spent %s in .fini (== 0x%0*lx)\n",
+			     DSO_FILENAME (maps[0]->l_name),
+			     DSO_FILENAME (l->l_name), buf,
+			     (int) sizeof (void *) * 2,
+			     (unsigned long int) (l->l_info[DT_FINI]->d_un.
+						  d_ptr));
+			}
+#endif
+		    }
 		}
 
 #ifdef SHARED
diff --git a/elf/dl-init.c b/elf/dl-init.c
index 2f85731..1c6a899 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.  */
@@ -27,6 +28,11 @@ typedef void (*init_t) (int, char **, char **);
 static void
 call_init (struct link_map *l, int argc, char **argv, char **env)
 {
+#if HP_TIMING_AVAIL
+  hp_timing_t init_time;
+  hp_timing_t start_time = 0;
+  hp_timing_t end_time;
+#endif
   if (l->l_init_called)
     /* This object is all done.  */
     return;
@@ -55,7 +61,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)
+    {
+#if HP_TIMING_AVAIL
+      if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME))
+	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);
+#if HP_TIMING_AVAIL
+      if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME))
+	{
+	  HP_TIMING_NOW (end_time);
+	  HP_TIMING_DIFF (init_time, start_time, end_time);
+	  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];
@@ -69,7 +95,29 @@ 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)
+	{
+#if HP_TIMING_AVAIL
+	  if (__glibc_unlikely
+	      (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME))
+	    HP_TIMING_NOW (start_time);
+#endif
 	((init_t) addrs[j]) (argc, argv, env);
+#if HP_TIMING_AVAIL
+	  if (__glibc_unlikely
+	      (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME))
+	    {
+	      HP_TIMING_NOW (end_time);
+	      HP_TIMING_DIFF (init_time, start_time, end_time);
+	      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 69873c2..2b8ac5e 100644
--- a/elf/rtld.c
+++ b/elf/rtld.c
@@ -2213,8 +2213,8 @@ process_dl_debug (const char *dl_debug)
   static const struct
   {
     unsigned char len;
-    const char name[10];
-    const char helptext[41];
+    const char name[16];
+    const char helptext[44];
     unsigned short int mask;
   } debopts[] =
     {
@@ -2241,6 +2241,12 @@ process_dl_debug (const char *dl_debug)
 	DL_DEBUG_STATISTICS },
       { LEN_AND_STR ("unused"), "determined unused DSOs",
 	DL_DEBUG_UNUSED },
+    // The "ctordtor_time" works only when HP_TIMING is available
+#if HP_TIMING_AVAIL
+      { LEN_AND_STR ("ctordtor_time"),
+	"display constructors/destructors statistics",
+	DL_DEBUG_CTORDTOR_TIME },
+#endif
       { LEN_AND_STR ("help"), "display this help message and exit",
 	DL_DEBUG_HELP },
     };
@@ -2300,7 +2306,7 @@ Valid options for the LD_DEBUG environment variable
are:\n\n");
 
       for (cnt = 0; cnt < ndebopts; ++cnt)
 	_dl_printf ("  %.*s%s%s\n", debopts[cnt].len, debopts[cnt].name,
-		    "         " + debopts[cnt].len - 3,
+		    "            " + debopts[cnt].len - 3,
 		    debopts[cnt].helptext);
 
       _dl_printf ("\n\
diff --git a/elf/tst-ctordtor_time.c b/elf/tst-ctordtor_time.c
new file mode 100644
index 0000000..de4a085
--- /dev/null
+++ b/elf/tst-ctordtor_time.c
@@ -0,0 +1,41 @@
+/* Test for LD_DEBUG=ctordtor_time option.
+
+   Copyright (C) 2004-2014 Free Software Foundation, Inc.
+   This file is part of the GNU C Library.
+   Contributed by Ulrich Drepper <drepper@redhat.com>, 2004.
+
+   The GNU C Library is free software; you can redistribute it and/or
+   modify it under the terms of the GNU Lesser General Public
+   License as published by the Free Software Foundation; either
+   version 2.1 of the License, or (at your option) any later version.
+
+   The GNU C Library is distributed in the hope that it will be useful,
+   but WITHOUT ANY WARRANTY; without even the implied warranty of
+   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+   Lesser General Public License for more details.
+
+   You should have received a copy of the GNU Lesser General Public
+   License along with the GNU C Library; if not, see
+   <http://www.gnu.org/licenses/>.  */
+#include <stdio.h>
+#include <stdlib.h>
+
+__attribute__ ((constructor))
+     static void main_ctor_func (void)
+{
+  printf ("\nfunction main_ctor_func invoked\n");
+  fflush (0);
+}
+
+__attribute__ ((destructor))
+     static void main_dtor_func (void)
+{
+  printf ("\nfunction main_dtor_func invoked\n");
+  fflush (0);
+}
+
+int
+main (void)
+{
+  return 0;
+}
diff --git a/elf/tst-ctordtor_time.sh b/elf/tst-ctordtor_time.sh
new file mode 100644
index 0000000..322b69b
--- /dev/null
+++ b/elf/tst-ctordtor_time.sh
@@ -0,0 +1,56 @@
+#! /bin/sh
+# Test for LD_DEBUG=ctordtor_time option.
+#
+# Copyright (C) 2015 Free Software Foundation, Inc.
+# This file is part of the GNU C Library.
+
+# The GNU C Library is free software; you can redistribute it and/or
+# modify it under the terms of the GNU Lesser General Public
+# License as published by the Free Software Foundation; either
+# version 2.1 of the License, or (at your option) any later version.
+
+# The GNU C Library is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+# Lesser General Public License for more details.
+
+# You should have received a copy of the GNU Lesser General Public
+# License along with the GNU C Library; if not, see
+# <http://www.gnu.org/licenses/>.
+
+set -o pipefail
+common_objpfx=$1
+test_program_prefix_before_env=$2
+run_program_env=$3
+test_program_prefix_after_env=$4
+
+TEST="tst-ctordtor_time"
+CTOR_OUTPUT="function main_ctor_func invoked"
+DTOR_OUTPUT="function main_dtor_func invoked"
+
+${test_program_prefix_before_env} ${run_program_env} LD_DEBUG=help
${test_program_prefix_after_env} ${common_objpfx}elf/$TEST
>${common_objpfx}elf/$TEST.out 2>&1
+grep "ctordtor_time" ${common_objpfx}elf/$TEST.out -wq
+if test $? -ne 0; then
+  echo "***LD_DEBUG=ctordtor_time is not supported on this platform"
+  exit 0
+fi
+
+${test_program_prefix_before_env} ${run_program_env} LD_DEBUG=ctordtor_time
${test_program_prefix_after_env}  ${common_objpfx}elf/$TEST
>>${common_objpfx}elf/$TEST.out 2>&1; status=$?
+if test $status -ne 0; then
+  echo "***Failed to run ${common_objpfx}elf/$TEST"
+  exit $status
+fi
+
+sed -n -e "/$CTOR_OUTPUT/,+1p" ${common_objpfx}elf/$TEST.out | sed -n '2p'
| grep "[0-9]\+:\s${common_objpfx}elf/$TEST => ${common_objpfx}elf/$TEST:
spent [0-9]\+ cycles in init (== 0x[0-9a-fA-F]\+)$" -q; status=$?
+if test $status -ne 0; then
+  echo "***LD_DEBUG=ctordtor_time log for constructor is not found in
output"
+  exit $status
+fi
+
+sed -n -e "/$DTOR_OUTPUT/,+1p" ${common_objpfx}elf/$TEST.out | sed -n '2p'
| grep "[0-9]\+:\s${common_objpfx}elf/$TEST => ${common_objpfx}elf/$TEST:
spent [0-9]\+ cycles in .fini_array\[[0-9]\+\] (== 0x[0-9a-fA-F]\+)$" -q;
status=$?
+if test $status -ne 0; then
+  echo "***LD_DEBUG=ctordtor_time log for destructor is not found in
output"
+  exit $status
+fi
+
+exit 0
diff --git a/sysdeps/generic/ldsodefs.h b/sysdeps/generic/ldsodefs.h
index 7a0fe8d..bb46504 100644
--- a/sysdeps/generic/ldsodefs.h
+++ b/sysdeps/generic/ldsodefs.h
@@ -462,6 +462,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_CTORDTOR_TIME   (1 << 12)
 
   /* OS version.  */
   EXTERN unsigned int _dl_osversion;
-- 
1.7.9.5


Regards,
Maria