New function log_clock.

* common/logging.c (log_clock): New.
* g10/gpg.c (set_debug): Print clock debug flag.
* g10/options.h (DBG_CLOCK_VALUE, DBG_CLOCK): New.
--

To actually use log_clock you need to enable the code in
logginc.c:log_check() and link against librt.  --debug 4096 may then
be used to enable it at runtime.

common/logging.c

@@ -857,6 +857,33 @@ log_printhex (const char *text, const void *buffer, size_t length)
 }
 
 
+void
+log_clock (const char *string)
+{
+#if 0
+  static unsigned long long initial;
+  struct timespec tv;
+  unsigned long long now;
+
+  if (clock_gettime (CLOCK_REALTIME, &tv))
+    {
+      log_debug ("error getting the realtime clock value\n");
+      return;
+    }
+  now = tv.tv_sec * 1000000000ull;
+  now += tv.tv_nsec;
+
+  if (!initial)
+    initial = now;
+
+  log_debug ("[%llu] %s", now - initial, string);
+#else
+  /* You need to link with -ltr to enable the above code.  */
+  log_debug ("[not enabled in the source] %s", string);
+#endif
+}
+
+
 #if __GNUC__ > 2 || (__GNUC__ == 2 && __GNUC_MINOR__ >= 5 )
 void
 bug_at( const char *file, int line, const char *func )

common/logging.h

@@ -96,5 +96,7 @@ void log_flush (void);
    by the hexdump and a final LF.  */
 void log_printhex (const char *text, const void *buffer, size_t length);
 
+void log_clock (const char *string);
+
 
 #endif /*LIBJNLIB_LOGGING_H*/

g10/gpg.c

@@ -1029,7 +1029,7 @@ set_debug (const char *level)
   gcry_control (GCRYCTL_SET_VERBOSITY, (int)opt.verbose);
 
   if (opt.debug)
-    log_info ("enabled debug flags:%s%s%s%s%s%s%s%s%s%s%s%s%s\n",
+    log_info ("enabled debug flags:%s%s%s%s%s%s%s%s%s%s%s%s%s%s\n",
               (opt.debug & DBG_PACKET_VALUE )? " packet":"",
               (opt.debug & DBG_MPI_VALUE    )? " mpi":"",
               (opt.debug & DBG_CIPHER_VALUE )? " cipher":"",
@@ -1042,7 +1042,8 @@ set_debug (const char *level)
               (opt.debug & DBG_HASHING_VALUE)? " hashing":"",
               (opt.debug & DBG_EXTPROG_VALUE)? " extprog":"",
               (opt.debug & DBG_CARD_IO_VALUE)? " cardio":"",
-              (opt.debug & DBG_ASSUAN_VALUE )? " assuan":"");
+              (opt.debug & DBG_ASSUAN_VALUE )? " assuan":"",
+              (opt.debug & DBG_CLOCK_VALUE  )? " clock":"");
 }
 
 
@@ -3114,6 +3115,8 @@ main (int argc, char **argv)
       }
 
     set_debug (debug_level);
+    if (DBG_CLOCK)
+      log_clock ("start");
 
     /* Do these after the switch(), so they can override settings. */
     if(PGP2)
@@ -4097,6 +4100,8 @@ void
 g10_exit( int rc )
 {
   gcry_control (GCRYCTL_UPDATE_RANDOM_SEED_FILE);
+  if (DBG_CLOCK)
+    log_clock ("stop");
   if ( (opt.debug & DBG_MEMSTAT_VALUE) )
     {
       gcry_control (GCRYCTL_DUMP_MEMORY_STATS);

g10/keydb.c

@@ -1156,6 +1156,9 @@ keydb_search2 (KEYDB_HANDLE hd, KEYDB_SEARCH_DESC *desc,
   if (!hd)
     return gpg_error (GPG_ERR_INV_ARG);
 
+  if (DBG_CLOCK)
+    log_clock ("keydb_search enter");
+
   rc = -1;
   while ((rc == -1 || gpg_err_code (rc) == GPG_ERR_EOF)
          && hd->current >= 0 && hd->current < hd->used)
@@ -1182,6 +1185,8 @@ keydb_search2 (KEYDB_HANDLE hd, KEYDB_SEARCH_DESC *desc,
         hd->found = hd->current;
     }
 
+  if (DBG_CLOCK)
+    log_clock ("keydb_search leave");
   return ((rc == -1 || gpg_err_code (rc) == GPG_ERR_EOF)
           ? gpg_error (GPG_ERR_NOT_FOUND)
           : rc);

g10/options.h

@@ -271,6 +271,7 @@ struct {
 #define DBG_HASHING_VALUE 512	/* debug hashing operations */
 #define DBG_EXTPROG_VALUE 1024  /* debug external program calls */
 #define DBG_CARD_IO_VALUE 2048  /* debug smart card I/O.  */
+#define DBG_CLOCK_VALUE   4096
 
 /* Fixme: For now alias this value.  */
 #define DBG_ASSUAN_VALUE  DBG_EXTPROG_VALUE
@@ -286,6 +287,7 @@ struct {
 #define DBG_EXTPROG (opt.debug & DBG_EXTPROG_VALUE)
 #define DBG_CARD_IO (opt.debug & DBG_CARD_IO_VALUE)
 #define DBG_ASSUAN  (opt.debug & DBG_ASSUAN_VALUE)
+#define DBG_CLOCK   (opt.debug & DBG_CLOCK_VALUE)
 
 /* FIXME: We need to check whey we did not put this into opt. */
 #define DBG_MEMORY    memory_debug_mode