[Pcsclite-cvs-commit] r5951 - in /trunk/PCSC/src: pcsc-spy.c pcsc-spy.py

[rousseau at users.alioth.debian.org]

Author: rousseau
Date: Tue Sep 13 12:20:15 2011
New Revision: 5951

URL: http://svn.debian.org/wsvn/pcsclite/?sc=1&rev=5951
Log:
Add Timing information

Modified:
    trunk/PCSC/src/pcsc-spy.c
    trunk/PCSC/src/pcsc-spy.py

Modified: trunk/PCSC/src/pcsc-spy.c
URL: http://svn.debian.org/wsvn/pcsclite/trunk/PCSC/src/pcsc-spy.c?rev=5951&op=diff
==============================================================================
--- trunk/PCSC/src/pcsc-spy.c (original)
+++ trunk/PCSC/src/pcsc-spy.c Tue Sep 13 12:20:15 2011
@@ -26,6 +26,7 @@
 #include <errno.h>
 #include <string.h>
 #include <unistd.h>
+#include <sys/time.h>
 
 #include "misc.h"
 #include <winscard.h>
@@ -123,9 +124,6 @@
 
 #define LOG log_line("%s:%d", __FILE__, __LINE__)
 
-#define Enter() spy_line("> %s", __FUNCTION__);
-#define Quit() spy_line("< %s: %s (0x%08X)", __FUNCTION__, pcsc_stringify_error(rv), rv)
-
 static int Log_fd = -1;
 
 #ifdef DEBUG
@@ -160,6 +158,26 @@
 	write(Log_fd, "\n", 1);
 	va_end(args);
 }
+
+static void spy_enter(const char *fname)
+{
+    struct timeval profile_time;
+
+    gettimeofday(&profile_time, NULL);
+    spy_line(">|%d|%d|%s", profile_time.tv_sec, profile_time.tv_usec, fname);
+}
+
+static void spy_quit(const char *fname, int rv)
+{
+    struct timeval profile_time;
+
+    gettimeofday(&profile_time, NULL);
+    spy_line("<|%d|%d|%s|%s (0x%08X)", profile_time.tv_sec,
+        profile_time.tv_usec, fname, pcsc_stringify_error(rv), rv);
+}
+
+#define Enter() spy_enter(__FUNCTION__)
+#define Quit() spy_quit(__FUNCTION__, rv)
 
 static void spy_long(long arg)
 {

Modified: trunk/PCSC/src/pcsc-spy.py
URL: http://svn.debian.org/wsvn/pcsclite/trunk/PCSC/src/pcsc-spy.py?rev=5951&op=diff
==============================================================================
--- trunk/PCSC/src/pcsc-spy.py (original)
+++ trunk/PCSC/src/pcsc-spy.py Tue Sep 13 12:20:15 2011
@@ -37,20 +37,29 @@
         if line == "":
             raise Exception("Empty line (application exited?)")
 
-        (function, rv) = line.split(':')
-        if function[0] != '<':
+        (direction, sec, usec, function, rv) = line.split('|')
+        if direction != '<':
             raise Exception("Wrong line:", line)
 
-        return rv
+        sec = int(sec)
+        usec = int(usec)
+        return (rv, sec, usec)
 
     def _log_rv(self):
         """ log the return value """
         line = self.filedesc.readline().strip()
-        rv = self._parse_rv(line)
+        (rv, sec, usec) = self._parse_rv(line)
+        delta_sec = sec - self.sec
+        delta_usec = usec - self.usec
+        if delta_usec < 0:
+            delta_sec -= 1
+            delta_usec += 1000000
+        a = b
+        time = " [%d.%09d]" % (delta_sec, delta_usec)
         if not "0x00000000" in rv:
-            print PCSCspy.color_red + " =>" + rv + PCSCspy.color_normal
+            print PCSCspy.color_red + " =>" + rv + PCSCspy.color_normal + time
         else:
-            print " =>", rv
+            print " =>", rv + time
 
     def log_in(self, line):
         """ generic log for IN line """
@@ -286,7 +295,9 @@
                 print "Garbage: ", line
             else:
                 # dispatch
-                fct = line[2:-1]
+                (direction, sec, usec, fct) = line.strip().split('|')
+                self.sec = int(sec)
+                self.usec = int(usec)
                 if fct == 'SCardEstablishContext':
                     self._SCardEstablishContext()
                 elif fct == 'SCardReleaseContext':