#54 more accurate profiling information

5 files changed, 84 insertions, 40 deletions

diff --git a/README.md b/README.md
index 4f916dc..e0b9ded 100644
--- a/README.md
+++ b/README.md
@@ -40,15 +40,15 @@ Requires xcode-8 command-line tools.
       make install      # release version
       make              # debug version
 
-      make fast_profile # release version with profiling information
-      make profile      # debug version with profiling information
-
 ### Usage
 
 ```
 -V | --verbose: Output debug information
     skhd -V
 
+-P | --profile: Output profiling information
+    skhd -P
+
 -v | --version: Print version number to stdout
     skhd -v
 
diff --git a/examples/skhdrc b/examples/skhdrc
index 747ccf7..ffd0613 100644
--- a/examples/skhdrc
+++ b/examples/skhdrc
@@ -260,4 +260,3 @@ ctrl + alt - s : chunkc tiling::desktop --layout monocle
 ctrl + alt - d : chunkc tiling::desktop --layout float
 
 ctrl + alt - w : chunkc tiling::desktop --deserialize ~/.chunkwm_layouts/dev_1
-
diff --git a/makefile b/makefile
index 50c5ee8..bbf993f 100644
--- a/makefile
+++ b/makefile
@@ -1,22 +1,16 @@
-FRAMEWORKS     = -framework Carbon
+FRAMEWORKS     = -framework Carbon -framework CoreAudio
 BUILD_PATH     = ./bin
 BUILD_FLAGS    = -std=c99 -Wall -g -O0
 SKHD_SRC       = ./src/skhd.c
 BINS           = $(BUILD_PATH)/skhd
 
-.PHONY: all clean install profile fast_profile
+.PHONY: all clean install
 
 all: clean $(BINS)
 
 install: BUILD_FLAGS=-std=c99 -O3
 install: clean $(BINS)
 
-profile: BUILD_FLAGS=-std=c99 -Wall -g -O0 -DSKHD_PROFILE
-profile: clean $(BINS)
-
-fast_profile: BUILD_FLAGS=-std=c99 -O3 -DSKHD_PROFILE
-fast_profile: clean $(BINS)
-
 clean:
 	rm -rf $(BUILD_PATH)
 
diff --git a/src/skhd.c b/src/skhd.c
index 77168c8..d586c9e 100644
--- a/src/skhd.c
+++ b/src/skhd.c
@@ -8,6 +8,7 @@
 #include <unistd.h>
 #include <Carbon/Carbon.h>
 
+#include "timing.h"
 #include "log.h"
 #define HASHTABLE_IMPLEMENTATION
 #include "hashtable.h"
@@ -34,30 +35,6 @@
 extern bool CGSIsSecureEventInputSet();
 #define secure_keyboard_entry_enabled CGSIsSecureEventInputSet
 
-#ifdef SKHD_PROFILE
-#define BEGIN_SCOPED_TIMED_BLOCK(note) \
-    do { \
-        char *timed_note = note; \
-        clock_t timed_block_begin = clock()
-#define END_SCOPED_TIMED_BLOCK() \
-        clock_t timed_block_end = clock(); \
-        double timed_block_elapsed = ((timed_block_end - timed_block_begin) / (double)CLOCKS_PER_SEC) * 1000.0f; \
-        printf("%.4fms (%s)\n", timed_block_elapsed, timed_note); \
-    } while (0)
-#define BEGIN_TIMED_BLOCK(note) \
-        char *timed_note = note; \
-        clock_t timed_block_begin = clock()
-#define END_TIMED_BLOCK() \
-        clock_t timed_block_end = clock(); \
-        double timed_block_elapsed = ((timed_block_end - timed_block_begin) / (double)CLOCKS_PER_SEC) * 1000.0f; \
-        printf("%.4fms (%s)\n", timed_block_elapsed, timed_note)
-#else
-#define BEGIN_SCOPED_TIMED_BLOCK(note)
-#define END_SCOPED_TIMED_BLOCK()
-#define BEGIN_TIMED_BLOCK(note)
-#define END_TIMED_BLOCK()
-#endif
-
 #define SKHD_CONFIG_FILE ".skhdrc"
 
 internal unsigned major_version = 0;
@@ -140,9 +117,10 @@ internal bool
 parse_arguments(int argc, char **argv)
 {
     int option;
-    const char *short_option = "Vvc:k:t:";
+    const char *short_option = "VPvc:k:t:";
     struct option long_option[] = {
         { "verbose", no_argument, NULL, 'V' },
+        { "profile", no_argument, NULL, 'P' },
         { "version", no_argument, NULL, 'v' },
         { "config", required_argument, NULL, 'c' },
         { "key", required_argument, NULL, 'k' },
@@ -155,6 +133,9 @@ parse_arguments(int argc, char **argv)
         case 'V': {
             verbose = true;
         } break;
+        case 'P': {
+            profile = true;
+        } break;
         case 'v': {
             printf("skhd version %d.%d.%d\n", major_version, minor_version, patch_version);
             return true;
@@ -214,12 +195,12 @@ use_default_config_path(void)
 
 int main(int argc, char **argv)
 {
-    BEGIN_TIMED_BLOCK("startup");
-    BEGIN_SCOPED_TIMED_BLOCK("initialization");
     if (parse_arguments(argc, argv)) {
         return EXIT_SUCCESS;
     }
 
+    BEGIN_SCOPED_TIMED_BLOCK("total_time");
+    BEGIN_SCOPED_TIMED_BLOCK("init");
     if (getuid() == 0 || geteuid() == 0) {
         error("skhd: running as root is not allowed! abort..\n");
     }
@@ -274,7 +255,7 @@ int main(int argc, char **argv)
         warn("skhd: could not watch '%s'\n", config_file);
     }
     END_SCOPED_TIMED_BLOCK();
-    END_TIMED_BLOCK();
+    END_SCOPED_TIMED_BLOCK();
 
     CFRunLoopRun();
     return EXIT_SUCCESS;
diff --git a/src/timing.h b/src/timing.h
new file mode 100644
index 0000000..44e91a8
--- /dev/null
+++ b/src/timing.h
@@ -0,0 +1,70 @@
+#ifndef MACOS_TIMING_H
+#define MACOS_TIMING_H
+
+#include <stdint.h>
+#include <CoreAudio/CoreAudio.h>
+
+#define BEGIN_SCOPED_TIMED_BLOCK(note) \
+    do { \
+        struct timing_info timing; \
+        if (profile) begin_timing(&timing, note)
+#define END_SCOPED_TIMED_BLOCK() \
+        if (profile) end_timing(&timing); \
+    } while (0)
+
+#define BEGIN_TIMED_BLOCK(note) \
+    struct timing_info timing; \
+    if (profile) begin_timing(&timing, note)
+#define END_TIMED_BLOCK() \
+    if (profile) end_timing(&timing)
+
+static bool profile;
+
+struct timing_info
+{
+    char *note;
+    uint64_t start;
+    uint64_t end;
+    float ms;
+};
+
+void begin_timing(struct timing_info *timing, char *note);
+void end_timing(struct timing_info *timing);
+
+static inline uint64_t
+macos_get_wall_clock(void)
+{
+    uint64_t result = AudioConvertHostTimeToNanos(AudioGetCurrentHostTime());
+    return result;
+}
+
+static inline float
+macos_get_seconds_elapsed(uint64_t start, uint64_t end)
+{
+    float result = ((float)(end - start) / 1000.0f) / 1000000.0f;
+    return result;
+}
+
+static inline float
+macos_get_milliseconds_elapsed(uint64_t start, uint64_t end)
+{
+    float result = 1000.0f * macos_get_seconds_elapsed(start, end);
+    return result;
+}
+
+void begin_timing(struct timing_info *timing, char *note) {
+    timing->note = note;
+    timing->start = macos_get_wall_clock();
+}
+
+void end_timing(struct timing_info *timing) {
+    timing->end = macos_get_wall_clock();
+    timing->ms  = macos_get_milliseconds_elapsed(timing->start, timing->end);
+    if (timing->note) {
+        printf("%6.4fms (%s)\n", timing->ms, timing->note);
+    } else {
+        printf("%6.4fms\n", timing->ms);
+    }
+}
+
+#endif