Add function-call time tracing for Linux/Android

Android/jni/jnihooks.c

@@ -217,6 +217,8 @@ void Java_org_deadc0de_apple2ix_Apple2Activity_nativeOnPause(JNIEnv *env, jobjec
 }
 
 void Java_org_deadc0de_apple2ix_Apple2Activity_nativeRender(JNIEnv *env, jobject obj) {
+    SCOPE_TRACE_VIDEO("nativeRender");
+
     if (UNLIKELY(appState != APP_RUNNING)) {
         if (appState == APP_REQUESTED_SHUTDOWN) {
             appState = APP_FINISHED;
@@ -281,6 +283,9 @@ void Java_org_deadc0de_apple2ix_Apple2Activity_nativeOnKeyUp(JNIEnv *env, jobjec
 
 jlong Java_org_deadc0de_apple2ix_Apple2Activity_nativeOnTouch(JNIEnv *env, jobject obj, jint action, jint pointerCount, jint pointerIndex, jfloatArray xCoords, jfloatArray yCoords) {
     //LOG(": %d/%d/%d :", action, pointerCount, pointerIndex);
+
+    SCOPE_TRACE_TOUCH("nativeOnTouch");
+
     if (UNLIKELY(appState != APP_RUNNING)) {
         return 0x0LL;
     }

Android/jni/sources.mk

@@ -30,7 +30,8 @@ APPLE2_AUDIO_SRC = \
 
 APPLE2_META_SRC = \
     $(APPLE2_SRC_PATH)/meta/debug.c $(APPLE2_SRC_PATH)/meta/debugger.c $(APPLE2_SRC_PATH)/meta/opcodes.c \
-    $(APPLE2_SRC_PATH)/test/sha1.c $(APPLE2_SRC_PATH)/json_parse.c $(APPLE2_SRC_PATH)/../externals/jsmn/jsmn.c
+    $(APPLE2_SRC_PATH)/meta/lintrace.c $(APPLE2_SRC_PATH)/test/sha1.c $(APPLE2_SRC_PATH)/json_parse.c \
+    $(APPLE2_SRC_PATH)/../externals/jsmn/jsmn.c
 
 APPLE2_MAIN_SRC = \
     $(APPLE2_SRC_PATH)/font.c $(APPLE2_SRC_PATH)/rom.c $(APPLE2_SRC_PATH)/misc.c $(APPLE2_SRC_PATH)/display.c $(APPLE2_SRC_PATH)/vm.c \

Makefile.am

@@ -14,7 +14,7 @@ noinst_HEADERS = src/common.h src/cpu.h src/disk.h src/glue.h src/vm.h \
 	src/timing.h src/uthash.h src/video/video.h src/zlib-helpers.h \
 	\
 	src/x86/glue-prologue.h \
-	src/meta/debug.h \
+	src/meta/debug.h src/meta/trace.h \
 	\
 	src/audio/alhelpers.h src/audio/AY8910.h src/audio/mockingboard.h \
 	src/audio/peripherals.h src/audio/soundcore.h src/audio/speaker.h \
@@ -48,8 +48,8 @@ AUDIO_SRC = \
 	src/audio/AY8910.c
 
 META_SRC = \
-	src/meta/debug.l src/meta/debugger.c src/meta/opcodes.c \
-	src/test/sha1.c
+	src/meta/debug.l src/meta/debugger.c src/meta/opcodes.c src/test/sha1.c \
+	src/meta/lintrace.c
 
 # NOTE : selectively enabled through configuration process ...
 EXTRA_apple2ix_SOURCES = \

src/audio/mockingboard.c

@@ -2110,6 +2110,7 @@ void MB_StartOfCpuExecute()
 // Called by ContinueExecution() at the end of every video frame
 void MB_EndOfVideoFrame()
 {
+    SCOPE_TRACE_AUDIO("MB_EndOfVideoFrame");
 	if(g_SoundcardType == CT_Empty)
 		return;
 
@@ -2126,6 +2127,7 @@ void MB_EndOfVideoFrame()
 // Called by CpuExecute() after every N opcodes (N = ~1000 @ 1MHz)
 void MB_UpdateCycles(void)
 {
+    SCOPE_TRACE_AUDIO("MB_UpdateCycles");
 	if(g_SoundcardType == CT_Empty)
 		return;
 

src/audio/speaker.c

@@ -395,6 +395,7 @@ void speaker_reset(void) {
 }
 
 void speaker_flush(void) {
+    SCOPE_TRACE_AUDIO("speaker_flush");
     if (!speaker_isAvailable) {
         return;
     }

src/common.h

@@ -63,6 +63,8 @@
 #include "prefs.h"
 #include "zlib-helpers.h"
 
+#include "meta/trace.h"
+
 #ifdef __APPLE__
 #include "darwin-shim.h"
 #import <CoreFoundation/CoreFoundation.h>

src/disk.c

@@ -110,6 +110,7 @@ static bool is_po(const char * const name) {
 #define NUM_SIXBIT_NIBS 342
 
 static void nibblize_sector(const uint8_t *src, uint8_t *out) {
+    SCOPE_TRACE_DISK("nibblize_sector");
 
     uint8_t work_buf[NUM_SIXBIT_NIBS];
     uint8_t *nib = work_buf;
@@ -168,6 +169,7 @@ static void nibblize_sector(const uint8_t *src, uint8_t *out) {
 }
 
 static void denibblize_sector(const uint8_t *src, uint8_t *out) {
+    SCOPE_TRACE_DISK("denibblize_sector");
 
     uint8_t work_buf[NUM_SIXBIT_NIBS+1];
     uint8_t *dsk = work_buf;
@@ -267,6 +269,7 @@ static void denibblize_sector(const uint8_t *src, uint8_t *out) {
 #define CODE44B(b) (((b) & 0x55) | 0xAA)
 
 static unsigned long nibblize_track(uint8_t *buf, int drive) {
+    SCOPE_TRACE_DISK("nibblize_track");
 
     uint8_t *output = disk6.disk[drive].track_image;
     
@@ -356,6 +359,8 @@ static unsigned long nibblize_track(uint8_t *buf, int drive) {
 }
 
 static void denibblize_track(int drive, uint8_t *dst) {
+    SCOPE_TRACE_DISK("denibblize_track");
+
     // Searches through the track data for each sector and decodes it
 #warning TODO FIXME inefficient -- refactor after moar tests =P
 
@@ -415,6 +420,7 @@ static void denibblize_track(int drive, uint8_t *dst) {
 }
 
 static bool load_track_data(void) {
+    SCOPE_TRACE_DISK("load_track_data");
 
     if (disk6.disk[disk6.drive].nibblized) {
         // .nib image
@@ -452,6 +458,7 @@ static bool load_track_data(void) {
 }
 
 static bool save_track_data(void) {
+    SCOPE_TRACE_DISK("save_track_data");
 
     if (disk6.disk[disk6.drive].nibblized) {
         // .nib image

src/meta/lintrace.c

@@ -0,0 +1,93 @@
+/*
+ * Apple // emulator for *nix
+ *
+ * This software package is subject to the GNU General Public License
+ * version 2 or later (your choice) as published by the Free Software
+ * Foundation.
+ *
+ * THERE ARE NO WARRANTIES WHATSOEVER.
+ *
+ */
+
+#if !defined(__linux__) || defined(NDEBUG)
+// Linux tracing should not be enabled for release builds
+#else
+
+#include "common.h"
+#include "trace.h"
+
+#define MAX_MSG_LEN 1024
+#define MAX_ARG_LEN 768
+
+#define TRACING_FILE "/sys/kernel/debug/tracing/trace_marker"
+
+#define FMT_TRACE_BEGIN       "B|%d|%s"
+#define FMT_TRACE_COUNT_BEGIN "C|%d|%s|%d"
+
+static int trace_fd = -1;
+static int trace_pid = -1;
+
+__attribute__((constructor(CTOR_PRIORITY_LATE)))
+static void _trace_init(void) {
+    TEMP_FAILURE_RETRY(trace_fd = open(TRACING_FILE, O_WRONLY));
+    if (trace_fd == -1) {
+        ERRLOG("Could not open kernel trace file");
+    } else {
+        LOG("Initialized Linux tracing facility");
+    }
+    trace_pid = getpid();
+}
+
+__attribute__((destructor(255)))
+static void _trace_shutdown(void) {
+    if (trace_fd != -1) {
+        TEMP_FAILURE_RETRY(close(trace_fd));
+        trace_fd = -1;
+    }
+}
+
+void trace_begin(const char *fmt, ...) {
+    if (trace_fd == -1) {
+        return;
+    }
+
+    va_list args;
+    va_start(args, fmt);
+    char args_buf[MAX_ARG_LEN] = { 0 };
+    vsnprintf(args_buf, MAX_ARG_LEN, fmt, args);
+    va_end(args);
+
+    char buf[MAX_MSG_LEN] = { 0 };
+    size_t length = snprintf(buf, MAX_MSG_LEN, FMT_TRACE_BEGIN, trace_pid, args_buf);
+    TEMP_FAILURE_RETRY(write(trace_fd, buf, length));
+}
+
+void trace_begin_count(uint32_t count, const char *fmt, ...) {
+    if (trace_fd == -1) {
+        return;
+    }
+
+    va_list args;
+    va_start(args, fmt);
+    char args_buf[MAX_ARG_LEN] = { 0 };
+    vsnprintf(args_buf, MAX_ARG_LEN, fmt, args);
+    va_end(args);
+
+    char buf[MAX_MSG_LEN] = { 0 };
+    size_t length = snprintf(buf, MAX_MSG_LEN, FMT_TRACE_COUNT_BEGIN, trace_pid, args_buf, count);
+    TEMP_FAILURE_RETRY(write(trace_fd, buf, length));
+}
+
+void trace_end(void) {
+    if (trace_fd == -1) {
+        return;
+    }
+    TEMP_FAILURE_RETRY(write(trace_fd, "E", 1));
+}
+
+void _trace_cleanup(void *token) {
+    trace_end();
+}
+
+#endif // whole file
+

src/meta/trace.h

@@ -0,0 +1,109 @@
+/*
+ * Apple // emulator for *nix
+ *
+ * This software package is subject to the GNU General Public License
+ * version 2 or later (your choice) as published by the Free Software
+ * Foundation.
+ *
+ * THERE ARE NO WARRANTIES WHATSOEVER.
+ *
+ */
+
+// Function tracing and profiling
+
+#ifndef _META_TRACE_H_
+#define _META_TRACE_H_
+
+#define TRACE_CPU 0
+#define TRACE_DISK 0
+#define TRACE_AUDIO 0
+#define TRACE_VIDEO 0
+#define TRACE_TOUCH 0
+
+#if !defined(__linux__)
+#   warning Linux-specific function call tracing and general profiling not enabled
+#else
+
+extern void _trace_cleanup(void *token);
+extern void _trace_begin(const char *fmt, ...);
+extern void _trace_begin_count(uint32_t count, const char *fmt, ...);
+extern void _trace_end(void);
+
+#define _SCOPE_TRACE(ctr, fmt, ...) \
+    void *__scope_token##ctr##__ __attribute__((cleanup(_trace_cleanup), unused)) = ({ _trace_begin(fmt, ##__VA_ARGS__); (void *)NULL; })
+
+#if !defined(NDEBUG)
+#   define SCOPE_TRACE(fmt, ...) _SCOPE_TRACE(_COUNTER_, fmt, ##__VA_ARGS__)
+
+#   if TRACE_CPU
+#       define SCOPE_TRACE_CPU(fmt, ...) SCOPE_TRACE(fmt, ##__VA_ARGS__)
+#       define TRACE_CPU_BEGIN(fmt, ...) _trace_begin(fmt, ##__VA_ARGS__)
+#       define TRACE_CPU_END() _trace_end()
+#   endif
+
+#   if TRACE_DISK
+#       define SCOPE_TRACE_DISK(fmt, ...) SCOPE_TRACE(fmt, ##__VA_ARGS__)
+#       define TRACE_DISK_BEGIN(fmt, ...) _trace_begin(fmt, ##__VA_ARGS__)
+#       define TRACE_DISK_END() _trace_end()
+#   endif
+
+#   if TRACE_AUDIO
+#       define SCOPE_TRACE_AUDIO(fmt, ...) SCOPE_TRACE(fmt, ##__VA_ARGS__)
+#       define TRACE_AUDIO_BEGIN(fmt, ...) _trace_begin(fmt, ##__VA_ARGS__)
+#       define TRACE_AUDIO_END() _trace_end()
+#   endif
+
+#   if TRACE_VIDEO
+#       define SCOPE_TRACE_VIDEO(fmt, ...) SCOPE_TRACE(fmt, ##__VA_ARGS__)
+#       define TRACE_VIDEO_BEGIN(fmt, ...) _trace_begin(fmt, ##__VA_ARGS__)
+#       define TRACE_VIDEO_END() _trace_end()
+#   endif
+
+#   if TRACE_TOUCH
+#       define SCOPE_TRACE_TOUCH(fmt, ...) SCOPE_TRACE(fmt, ##__VA_ARGS__)
+#       define TRACE_TOUCH_BEGIN(fmt, ...) _trace_begin(fmt, ##__VA_ARGS__)
+#       define TRACE_TOUCH_END() _trace_end()
+#   endif
+
+#endif
+
+#endif // __linux__
+
+#if !defined(SCOPE_TRACE)
+#   define SCOPE_TRACE(fmt, ...)
+#endif
+
+#if !TRACE_CPU
+#   define SCOPE_TRACE_CPU(fmt, ...)
+#   define TRACE_CPU_BEGIN(fmt, ...)
+#   define TRACE_CPU_END()
+#endif
+
+#if !TRACE_DISK
+#   define SCOPE_TRACE_DISK(fmt, ...)
+#   define TRACE_DISK_BEGIN(fmt, ...)
+#   define TRACE_DISK_END()
+#endif
+
+#if !TRACE_AUDIO
+#   define SCOPE_TRACE_AUDIO(fmt, ...)
+#   define TRACE_AUDIO_BEGIN(fmt, ...)
+#   define TRACE_AUDIO_END()
+#endif
+
+#if !TRACE_VIDEO
+#   define SCOPE_TRACE_VIDEO(fmt, ...)
+#   define TRACE_VIDEO_BEGIN(fmt, ...)
+#   define TRACE_VIDEO_END()
+#endif
+
+#if !TRACE_TOUCH
+#   define SCOPE_TRACE_TOUCH(fmt, ...)
+#   define TRACE_TOUCH_BEGIN(fmt, ...)
+#   define TRACE_TOUCH_END()
+#endif
+
+#else
+
+#endif // whole file
+

src/timing.c

@@ -307,6 +307,7 @@ static void *cpu_thread(void *dummyptr) {
         clock_gettime(CLOCK_MONOTONIC, &t0);
 
         do {
+            SCOPE_TRACE_CPU("CPU mainloop");
             // -LOCK----------------------------------------------------------------------------------------- SAMPLE ti
 #ifdef AUDIO_ENABLED
             if (UNLIKELY(emul_pause_audio)) {
@@ -450,7 +451,9 @@ static void *cpu_thread(void *dummyptr) {
                 {
                     deltat.tv_sec = 0;
                     deltat.tv_nsec = sleepfor;
+                    TRACE_CPU_BEGIN("sleep");
                     nanosleep(&deltat, NULL);
+                    TRACE_CPU_END();
                 }
 
 #if DEBUG_TIMING

src/video/glnode.c

@@ -86,6 +86,7 @@ void glnode_shutdownNodes(void) {
 }
 
 void glnode_renderNodes(void) {
+    SCOPE_TRACE_VIDEO("glnode render");
     glnode_array_node_s *p = tail;
     while (p) {
         p->node.render();
@@ -103,6 +104,7 @@ void glnode_reshapeNodes(int w, int h) {
 
 #if INTERFACE_TOUCH
 int64_t glnode_onTouchEvent(interface_touch_event_t action, int pointer_count, int pointer_idx, float *x_coords, float *y_coords) {
+    SCOPE_TRACE_TOUCH("glnode onTouchEvent");
     glnode_array_node_s *p = head;
     int64_t flags = 0x0;
     while (p) {

src/video/glvideo.c

@@ -726,6 +726,8 @@ static void gldriver_update(int unused) {
 #endif
 
 static void gldriver_render(void) {
+    SCOPE_TRACE_VIDEO("glvideo render");
+
     const uint8_t * const fb = video_current_framebuffer();
     if (UNLIKELY(!fb)) {
         return;
@@ -769,6 +771,7 @@ static void gldriver_render(void) {
 
     char pixels[SCANWIDTH * SCANHEIGHT * sizeof(PIXEL_TYPE)]; // HACK FIXME TODO ... are we sure this does not overflow max stack buffer size?
     if (wasDirty) {
+        SCOPE_TRACE_VIDEO("pixel convert");
         // Update texture from indexed-color Apple //e internal framebuffer
         unsigned int count = SCANWIDTH * SCANHEIGHT;
         for (unsigned int i=0, j=0; i<count; i++, j+=sizeof(PIXEL_TYPE)) {
@@ -786,6 +789,7 @@ static void gldriver_render(void) {
     glBindTexture(GL_TEXTURE_2D, a2TextureName);
     glUniform1i(texSamplerLoc, TEXTURE_ID_FRAMEBUFFER);
     if (wasDirty) {
+        SCOPE_TRACE_VIDEO("glvideo texImage2D");
         _HACKAROUND_GLTEXIMAGE2D_PRE(TEXTURE_ACTIVE_FRAMEBUFFER, a2TextureName);
         glTexImage2D(GL_TEXTURE_2D, /*level*/0, TEX_FORMAT_INTERNAL, SCANWIDTH, SCANHEIGHT, /*border*/0, TEX_FORMAT, TEX_TYPE, (GLvoid *)&pixels[0]);
     }