From db4a71ca6f5325d54468754aa814460068226085 Mon Sep 17 00:00:00 2001 From: Aaron Culliney Date: Fri, 23 Nov 2018 10:35:38 -0800 Subject: [PATCH] Enable Chromium systrace for all platforms --- Android/jni/jnihooks.c | 2 +- Android/jni/sources.mk | 2 +- Apple2Mac/Apple2Mac.xcodeproj/project.pbxproj | 36 ++- Makefile.am | 2 +- src/audio/mockingboard.c | 4 + src/common.h | 2 +- src/display.c | 2 + src/interface.c | 1 + src/joystick.c | 1 + src/meta/systrace.c | 255 +++++++++++++++--- src/meta/systrace.h | 86 +++--- src/timing.c | 9 +- src/video/glnode.c | 2 +- src/video/gltouchjoy_joy.c | 1 + src/video/video.c | 5 + 15 files changed, 326 insertions(+), 84 deletions(-) diff --git a/Android/jni/jnihooks.c b/Android/jni/jnihooks.c index c1042e89..511be03d 100644 --- a/Android/jni/jnihooks.c +++ b/Android/jni/jnihooks.c @@ -337,7 +337,7 @@ void Java_org_deadc0de_apple2ix_Apple2View_nativeOnJoystickMove(JNIEnv *env, jcl jlong Java_org_deadc0de_apple2ix_Apple2View_nativeOnTouch(JNIEnv *env, jclass cls, jint action, jint pointerCount, jint pointerIndex, jfloatArray xCoords, jfloatArray yCoords) { //LOG(": %d/%d/%d :", action, pointerCount, pointerIndex); - SCOPE_TRACE_TOUCH("nativeOnTouch"); + SCOPE_TRACE_INTERFACE("nativeOnTouch"); if (UNLIKELY(appState != APP_RUNNING)) { return 0x0LL; diff --git a/Android/jni/sources.mk b/Android/jni/sources.mk index a1cf6f18..53038b98 100644 --- a/Android/jni/sources.mk +++ b/Android/jni/sources.mk @@ -38,7 +38,7 @@ APPLE2_AUDIO_SRC = \ APPLE2_META_SRC = \ $(APPLE2_SRC_PATH)/meta/debug.c \ $(APPLE2_SRC_PATH)/meta/debugger.c \ - $(APPLE2_SRC_PATH)/meta/lintrace.c \ + $(APPLE2_SRC_PATH)/meta/systrace.c \ $(APPLE2_SRC_PATH)/meta/log.c \ $(APPLE2_SRC_PATH)/meta/memmngt.c \ $(APPLE2_SRC_PATH)/meta/opcodes.c \ diff --git a/Apple2Mac/Apple2Mac.xcodeproj/project.pbxproj b/Apple2Mac/Apple2Mac.xcodeproj/project.pbxproj index 3ff57008..71b3dc97 100644 --- a/Apple2Mac/Apple2Mac.xcodeproj/project.pbxproj +++ b/Apple2Mac/Apple2Mac.xcodeproj/project.pbxproj @@ -145,6 +145,20 @@ 4A589F85215831560026A73A /* ntsc.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A589F722157E72B0026A73A /* ntsc.c */; }; 4A609CB31D725D4C0066AF38 /* external-disks in Resources */ = {isa = PBXBuildFile; fileRef = 4A609CB21D725D4C0066AF38 /* external-disks */; }; 4A6746721D848B51006520C2 /* external-disks in Resources */ = {isa = PBXBuildFile; fileRef = 4A609CB21D725D4C0066AF38 /* external-disks */; }; + 4A68078C21A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68078D21A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68078E21A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68078F21A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68079021A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68079121A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68079221A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68079321A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68079421A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68079521A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68079621A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68079721A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68079821A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; + 4A68079921A86FF200D4A353 /* systrace.c in Sources */ = {isa = PBXBuildFile; fileRef = 4A68078B21A86FF200D4A353 /* systrace.c */; }; 4A69C1921A33DB90001579EF /* DDHidLib.framework in Copy Files (1 item) */ = {isa = PBXBuildFile; fileRef = 77C2796F1A1047AF000FE33F /* DDHidLib.framework */; settings = {ATTRIBUTES = (CodeSignOnCopy, RemoveHeadersOnCopy, ); }; }; 4A6B7C8D1D39E98C00A02120 /* disks in Resources */ = {isa = PBXBuildFile; fileRef = 4ACD73191D205D6000123DE6 /* disks */; }; 4A6B7C8E1D39E9E000A02120 /* disks in Resources */ = {isa = PBXBuildFile; fileRef = 4ACD73191D205D6000123DE6 /* disks */; }; @@ -965,6 +979,8 @@ 4A4B676B1DB47682005028A6 /* Apple2iOSTestUI-Info.plist */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = text.plist.xml; path = "Apple2iOSTestUI-Info.plist"; sourceTree = ""; }; 4A589F722157E72B0026A73A /* ntsc.c */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.c; path = ntsc.c; sourceTree = ""; }; 4A609CB21D725D4C0066AF38 /* external-disks */ = {isa = PBXFileReference; lastKnownFileType = folder; name = "external-disks"; path = "../external-disks"; sourceTree = ""; }; + 4A68078A21A86FDD00D4A353 /* systrace.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = systrace.h; sourceTree = ""; }; + 4A68078B21A86FF200D4A353 /* systrace.c */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.c; path = systrace.c; sourceTree = ""; }; 4A7EDC911AE092680072E98A /* glhudmodel.c */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.c; path = glhudmodel.c; sourceTree = ""; }; 4A7EDC921AE092680072E98A /* glnode.c */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.c; path = glnode.c; sourceTree = ""; }; 4A7EDC9D1AE092B80072E98A /* interface.c */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.c; path = interface.c; sourceTree = ""; }; @@ -996,7 +1012,6 @@ 4AD4FEC41A52464F00F958EC /* Apple2MacTestDisk-Info.plist */ = {isa = PBXFileReference; lastKnownFileType = text.plist.xml; name = "Apple2MacTestDisk-Info.plist"; path = "Apple2MacTests/Apple2MacTestDisk-Info.plist"; sourceTree = SOURCE_ROOT; }; 4AD4FEC91A52467D00F958EC /* testdisk.c */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.c; path = testdisk.c; sourceTree = ""; }; 4ADB475B209E300D00CD2985 /* log.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = log.h; sourceTree = ""; }; - 4ADB475C209E302800CD2985 /* trace.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = trace.h; sourceTree = ""; }; 4ADB475D209E9A2600CD2985 /* glue-offsets.c */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.c; path = "glue-offsets.c"; sourceTree = ""; }; 4ADB475F209E9A6800CD2985 /* genrom.c */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.c; path = genrom.c; sourceTree = ""; }; 4ADB4760209E9A8900CD2985 /* genfont.c */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.c; path = genfont.c; sourceTree = ""; }; @@ -1008,7 +1023,6 @@ 4AEDCEE8209E9BF70090B44F /* glue-offsets.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = "glue-offsets.h"; path = "arm/glue-offsets.h"; sourceTree = ""; }; 4AEDCEED209E9C0E0090B44F /* glue-offsets32.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; name = "glue-offsets32.h"; path = "arm/glue-offsets32.h"; sourceTree = ""; }; 4AEDCEEE209E9C520090B44F /* soundcore-opensles.c */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.c; path = "soundcore-opensles.c"; sourceTree = ""; }; - 4AEDCEEF209E9C930090B44F /* lintrace.c */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.c; path = lintrace.c; sourceTree = ""; }; 4AEDCEF0209E9CCA0090B44F /* shatest.c */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.c; path = shatest.c; sourceTree = ""; }; 4AEDCEF1209E9CF10090B44F /* sha1-license.txt */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = text; path = "sha1-license.txt"; sourceTree = ""; }; 4AEDCEF3209E9D280090B44F /* xvideo.c */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.c; path = xvideo.c; sourceTree = ""; }; @@ -1518,8 +1532,8 @@ 773B3D7019568A570085CE5F /* meta */ = { isa = PBXGroup; children = ( - 4AEDCEEF209E9C930090B44F /* lintrace.c */, - 4ADB475C209E302800CD2985 /* trace.h */, + 4A68078B21A86FF200D4A353 /* systrace.c */, + 4A68078A21A86FDD00D4A353 /* systrace.h */, 4ADB475B209E300D00CD2985 /* log.h */, 4A8F5D3B1F6A271700AE37B5 /* log.c */, 4A8F5D081F6A1FC900AE37B5 /* darwin-shim.c */, @@ -2836,6 +2850,7 @@ 4A4B67071DB4723F005028A6 /* joystick.c in Sources */, 4A4B67081DB4723F005028A6 /* iosPrefControllerViewController.m in Sources */, 4A4B67091DB4723F005028A6 /* sha1.c in Sources */, + 4A68079721A86FF200D4A353 /* systrace.c in Sources */, 4A4B670A1DB4723F005028A6 /* keys.c in Sources */, 4A4B670B1DB4723F005028A6 /* AppDelegate.m in Sources */, 4A4B670C1DB4723F005028A6 /* main.m in Sources */, @@ -2896,6 +2911,7 @@ 4A4B67511DB47560005028A6 /* joystick.c in Sources */, 4A4B67521DB47560005028A6 /* iosPrefControllerViewController.m in Sources */, 4A4B67531DB47560005028A6 /* sha1.c in Sources */, + 4A68079821A86FF200D4A353 /* systrace.c in Sources */, 4A4B67541DB47560005028A6 /* keys.c in Sources */, 4A4B67551DB47560005028A6 /* AppDelegate.m in Sources */, 4A4B67561DB47560005028A6 /* main.m in Sources */, @@ -2944,6 +2960,7 @@ 4A8A403D1D85CEEE00B460B0 /* font.c in Sources */, 4A8A403E1D85CEEE00B460B0 /* cpu-supp.c in Sources */, 4A8A403F1D85CEEE00B460B0 /* vm.c in Sources */, + 4A68079121A86FF200D4A353 /* systrace.c in Sources */, 4A8A40401D85CEEE00B460B0 /* darwin-glue.S in Sources */, 4A8A40411D85CEEE00B460B0 /* soundcore.c in Sources */, 4A8A40421D85CEEE00B460B0 /* matrixUtil.c in Sources */, @@ -2996,6 +3013,7 @@ 4ABDA9B41D792E8C0086A35B /* font.c in Sources */, 4ABDA9B51D792E8C0086A35B /* cpu-supp.c in Sources */, 4ABDA9B61D792E8C0086A35B /* vm.c in Sources */, + 4A68079021A86FF200D4A353 /* systrace.c in Sources */, 4ABDA9B71D792E8C0086A35B /* darwin-glue.S in Sources */, 4ABDA9B81D792E8C0086A35B /* soundcore.c in Sources */, 4ABDA9B91D792E8C0086A35B /* matrixUtil.c in Sources */, @@ -3060,6 +3078,7 @@ 4ACD734C1D20A83E00123DE6 /* joystick.c in Sources */, 4ACD734D1D20A83E00123DE6 /* iosPrefControllerViewController.m in Sources */, 4ACD734E1D20A83E00123DE6 /* sha1.c in Sources */, + 4A68079421A86FF200D4A353 /* systrace.c in Sources */, 4ACD734F1D20A83E00123DE6 /* keys.c in Sources */, 4ACD73501D20A83E00123DE6 /* AppDelegate.m in Sources */, 4ACD73511D20A83E00123DE6 /* main.m in Sources */, @@ -3120,6 +3139,7 @@ 4ACD739D1D20AB6A00123DE6 /* joystick.c in Sources */, 4ACD739E1D20AB6A00123DE6 /* iosPrefControllerViewController.m in Sources */, 4ACD739F1D20AB6A00123DE6 /* sha1.c in Sources */, + 4A68079921A86FF200D4A353 /* systrace.c in Sources */, 4ACD73A01D20AB6A00123DE6 /* keys.c in Sources */, 4ACD73A11D20AB6A00123DE6 /* AppDelegate.m in Sources */, 4ACD73A21D20AB6A00123DE6 /* main.m in Sources */, @@ -3180,6 +3200,7 @@ 4ACD73ED1D20B11D00123DE6 /* joystick.c in Sources */, 4ACD73EE1D20B11D00123DE6 /* iosPrefControllerViewController.m in Sources */, 4ACD73EF1D20B11D00123DE6 /* sha1.c in Sources */, + 4A68079521A86FF200D4A353 /* systrace.c in Sources */, 4ACD73F01D20B11D00123DE6 /* keys.c in Sources */, 4ACD73F11D20B11D00123DE6 /* AppDelegate.m in Sources */, 4ACD73F21D20B11D00123DE6 /* main.m in Sources */, @@ -3240,6 +3261,7 @@ 4ACD74531D26210600123DE6 /* joystick.c in Sources */, 4ACD74541D26210600123DE6 /* iosPrefControllerViewController.m in Sources */, 4ACD74551D26210600123DE6 /* sha1.c in Sources */, + 4A68079621A86FF200D4A353 /* systrace.c in Sources */, 4ACD74561D26210600123DE6 /* keys.c in Sources */, 4ACD74571D26210600123DE6 /* AppDelegate.m in Sources */, 4ACD74581D26210600123DE6 /* main.m in Sources */, @@ -3288,6 +3310,7 @@ 4AD4FEA91A52464F00F958EC /* font.c in Sources */, 4AD4FEAA1A52464F00F958EC /* cpu-supp.c in Sources */, 4AD4FEAB1A52464F00F958EC /* vm.c in Sources */, + 4A68078E21A86FF200D4A353 /* systrace.c in Sources */, 4AD4FEAC1A52464F00F958EC /* darwin-glue.S in Sources */, 4ACD74121D261A1300123DE6 /* soundcore.c in Sources */, 4AD4FEAD1A52464F00F958EC /* matrixUtil.c in Sources */, @@ -3340,6 +3363,7 @@ 4ADC521319E8CA4500186B36 /* font.c in Sources */, 4ADC521419E8CA4500186B36 /* cpu-supp.c in Sources */, 4ADC521519E8CA4500186B36 /* vm.c in Sources */, + 4A68079221A86FF200D4A353 /* systrace.c in Sources */, 4ADC521619E8CA4500186B36 /* darwin-glue.S in Sources */, 4ACD74141D261A1500123DE6 /* soundcore.c in Sources */, 4ADC521719E8CA4500186B36 /* matrixUtil.c in Sources */, @@ -3398,6 +3422,7 @@ 77E1C0B519D72700004344E0 /* modelUtil.c in Sources */, 773B3DAC19568A570085CE5F /* debug.l in Sources */, 935C55161C12B61D0013166D /* EmulatorJoystickCalibrationView.m in Sources */, + 4A68078C21A86FF200D4A353 /* systrace.c in Sources */, 779F565919EAF66E00A6F107 /* AY8910.c in Sources */, 935C55181C12B61D0013166D /* EmulatorPrefsController.m in Sources */, 93BC72571BF6FF11005CDFCA /* playqueue.c in Sources */, @@ -3460,6 +3485,7 @@ 779DD83D195BD9F900DF89E5 /* font.c in Sources */, 779DD83E195BD9F900DF89E5 /* cpu-supp.c in Sources */, 779DD83F195BD9F900DF89E5 /* vm.c in Sources */, + 4A68078D21A86FF200D4A353 /* systrace.c in Sources */, 779DD840195BD9F900DF89E5 /* darwin-glue.S in Sources */, 4ACD74111D261A1200123DE6 /* soundcore.c in Sources */, 4ADC51C519E8BD4000186B36 /* matrixUtil.c in Sources */, @@ -3512,6 +3538,7 @@ 779F567919EB0B9100A6F107 /* font.c in Sources */, 779F567A19EB0B9100A6F107 /* cpu-supp.c in Sources */, 779F567B19EB0B9100A6F107 /* vm.c in Sources */, + 4A68078F21A86FF200D4A353 /* systrace.c in Sources */, 779F567C19EB0B9100A6F107 /* darwin-glue.S in Sources */, 4ACD74131D261A1400123DE6 /* soundcore.c in Sources */, 779F567D19EB0B9100A6F107 /* matrixUtil.c in Sources */, @@ -3560,6 +3587,7 @@ 935C55511C136DF40013166D /* alhelpers.c in Sources */, 935C55521C136DF40013166D /* AY8910.c in Sources */, 935C55531C136DF40013166D /* mockingboard.c in Sources */, + 4A68079321A86FF200D4A353 /* systrace.c in Sources */, 935C55541C136DF40013166D /* playqueue.c in Sources */, 935C558E1C1370800013166D /* gltouchmenu.c in Sources */, 935C55571C136DF40013166D /* speaker.c in Sources */, diff --git a/Makefile.am b/Makefile.am index 6a2bf81a..349938bb 100644 --- a/Makefile.am +++ b/Makefile.am @@ -66,7 +66,7 @@ apple2ix_SOURCES = \ src/meta/darwin-shim.c \ src/meta/debug.l \ src/meta/debugger.c \ - src/meta/lintrace.c \ + src/meta/systrace.c \ src/meta/log.c \ src/meta/memmngt.c \ src/meta/opcodes.c \ diff --git a/src/audio/mockingboard.c b/src/audio/mockingboard.c index 703e2e81..7d12fd71 100644 --- a/src/audio/mockingboard.c +++ b/src/audio/mockingboard.c @@ -956,6 +956,7 @@ static void MB_Update() { return; } + SCOPE_TRACE_AUDIO("MB_Update ..."); # if MB_TRACING if (mb_trace_fp) { fprintf(mb_trace_fp, "%s", "\tMB_Update()\n"); @@ -1285,6 +1286,7 @@ static DWORD WINAPI SSI263Thread(LPVOID lpParameter) #else static void* SSI263Thread(void *lpParameter) { + TRACE_AUDIO_MARK("SSI263Thread ..."); const unsigned long nsecWait = NANOSECONDS_PER_SECOND / audio_getCurrentBackend()->systemSettings.sampleRateHz; const struct timespec wait = { .tv_sec=0, .tv_nsec=nsecWait }; @@ -2368,6 +2370,8 @@ void MB_UpdateCycles(ULONG uExecutedCycles) if(g_SoundcardType == CT_Empty) return; + SCOPE_TRACE_AUDIO("MB_UpdateCycles"); + timing_checkpointCycles(); unsigned long uCycles = cycles_count_total - g_uLastCumulativeCycles; g_uLastCumulativeCycles = cycles_count_total; diff --git a/src/common.h b/src/common.h index 5b6fe674..880e817f 100644 --- a/src/common.h +++ b/src/common.h @@ -79,7 +79,7 @@ #include "prefs.h" #include "zlib-helpers.h" -#include "meta/trace.h" +#include "meta/systrace.h" #if __APPLE__ # include "meta/darwin-shim.h" diff --git a/src/display.c b/src/display.c index 100535c3..d2611784 100644 --- a/src/display.c +++ b/src/display.c @@ -994,6 +994,8 @@ void display_flushScanline(scan_data_t *scandata) { void display_frameComplete(void) { ASSERT_ON_CPU_THREAD(); + SCOPE_TRACE_CPU("frameComplete"); + video_setDirty(FB_DIRTY_FLAG); #if TESTING diff --git a/src/interface.c b/src/interface.c index fa8b24b4..01ca1611 100644 --- a/src/interface.c +++ b/src/interface.c @@ -1488,6 +1488,7 @@ typedef struct interface_key_s { static void *interface_thread(void *data) { + SCOPE_TRACE_INTERFACE("interface_thread ..."); interface_thread_id = pthread_self(); cpu_pause(); diff --git a/src/joystick.c b/src/joystick.c index c7a09a91..3e8a5a04 100644 --- a/src/joystick.c +++ b/src/joystick.c @@ -273,6 +273,7 @@ void c_calibrate_joystick() // race, but hopefully much less likely to trigger). static void *_joystick_resetDelayed(void *ctx) { (void)ctx; + SCOPE_TRACE_INTERFACE("_joystick_resetDelayed"); // delay sleep(1); diff --git a/src/meta/systrace.c b/src/meta/systrace.c index 4ddf4c39..b47d2593 100644 --- a/src/meta/systrace.c +++ b/src/meta/systrace.c @@ -5,55 +5,222 @@ * version 3 or later (your choice) as published by the Free Software * Foundation. * - * Copyright 2013-2015 Aaron Culliney + * Copyright 2013-2018 Aaron Culliney * */ -#if !defined(__linux__) || defined(NDEBUG) -// Linux tracing should not be enabled for release builds -#else - #include "common.h" -#include "trace.h" + +#if ENABLE_SYSTRACING + +#if defined(__linux__) +// Linux (and Android) have kernel support via ftrace (atrace) : https://www.kernel.org/doc/Documentation/trace/ftrace.txt +#else +# if !USE_CUSTOM_TRACE_FILE +# error not on Linux, must use USE_CUSTOM_TRACE_FILE ... +# endif +#endif #include #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" +#define CLOCK_GETTIME() \ + struct timespec ts; \ + clock_gettime(CLOCK_MONOTONIC, &ts); \ + long secs = ts.tv_sec; \ + long usecs = ts.tv_nsec / 1000; static int trace_fd = -1; -static int trace_pid = -1; + +#if !USE_CUSTOM_TRACE_FILE + +# define FMT_TRACE_BEGIN "B|%lu|%s" +# define FMT_TRACE_CBEGIN "C|%lu|%s|%d" +# define FMT_TRACE_END "E" +# define TRACING_PATH "/sys/kernel/debug/tracing/trace_marker" +# define OPEN_FLAGS (O_WRONLY) +# define MODE_FLAGS (0) + +#else + +# define FMT_TRACE_BEGIN "a2ix-%lu [000] ...1 %ld%c%06ld: tracing_mark_write: B|%lu|%s\n" +# define FMT_TRACE_CBEGIN "a2ix-%lu [000] ...1 %ld%c%06ld: tracing_mark_write: C|%lu|%s|%d\n" +# define FMT_TRACE_END "a2ix-%lu [000] ...1 %ld%c%06ld: tracing_mark_write: E\n" +# define TRACE_BUF_SIZ (2*1024*1024) +# define OPEN_FLAGS (O_RDWR|O_CREAT|O_TRUNC) +# define MODE_FLAGS (S_IRUSR|S_IWUSR|S_IRGRP|S_IROTH) +# define FILE_WRITER_USLEEP 10 + +static pthread_t systrace_thread_id = 0; +static bool systrace_thread_initialized = false; + +static long writerGate = 0; // prevent writing in systrace_thread critical section +static char *writeBuf0 = NULL; // allocated +static char *writeBuf1 = NULL; // (non-allocated contiguous) == writeBuf0 + TRACE_BUF_SIZ +static char *writeHead = NULL; + +static void _write_trace(char *srcBuf, unsigned long length) { + if (UNLIKELY(length <= 0)) { + assert(false && "invalid input"); + return; + } + + // gated swizzle writeHead (wait if necessary for systrace_thread to exit critical section) + long gate; + do { + gate = __sync_add_and_fetch(&writerGate, 1); + if (LIKELY(gate > 0)) { + break; + } + __sync_sub_and_fetch(&writerGate, 1); + usleep(1); + } while(1); + char *dstBuf = __sync_fetch_and_add(&writeHead, (void *)length); + __sync_sub_and_fetch(&writerGate, 1); + + // sanity check buffer overflow + uintptr_t idx0 = dstBuf - writeBuf0; + uintptr_t idx1 = dstBuf - writeBuf1; + uintptr_t idx = idx0 < idx1 ? idx0 : idx1; + if (UNLIKELY((idx + length) > TRACE_BUF_SIZ)) { + assert(false && "avoided buffer overflow, please adjust buffer size or FILE_WRITER_USLEEP ..."); + return; + } + + memcpy(dstBuf, srcBuf, length); +} + +static void *systrace_thread(void *ignored) { + (void)ignored; + + LOG("Starting systrace writer thread ..."); + + writeBuf0 = CALLOC(1, TRACE_BUF_SIZ); + assert(writeBuf0); + writeBuf1 = CALLOC(1, TRACE_BUF_SIZ); + assert(writeBuf1); + + bool swapped = __sync_bool_compare_and_swap(&writeHead, /*oldval:*/NULL, /*newval:*/writeBuf0); + assert(swapped); + + systrace_thread_initialized = true; + + char *currBuf = writeBuf0; + char *otherBuf = writeBuf1; + while (LIKELY(systrace_thread_initialized)) { + + // gated swap of writeHead to otherBuf ... wait for writers if necessary + long gate; + do { + gate = __sync_sub_and_fetch(&writerGate, 10000); + if (LIKELY(gate == -10000)) { + break; + } + __sync_add_and_fetch(&writerGate, 10000); + usleep(FILE_WRITER_USLEEP); + } while(1); + char *p = __sync_val_compare_and_swap(&writeHead, /*oldval:*/writeHead, /*newval:*/otherBuf); + __sync_add_and_fetch(&writerGate, 10000); + + // swap active buffer ... + char *oldBuf = currBuf; + currBuf = otherBuf; + otherBuf = oldBuf; + + size_t length = p - oldBuf; + if (length == 0) { + // no traces to write + usleep(FILE_WRITER_USLEEP); + continue; + } + + if (UNLIKELY(length > TRACE_BUF_SIZ)) { + length = TRACE_BUF_SIZ; + } + + // heuristic : if NUL bytes found in trace buffer, we need to wait for lingering writers to finish + while (1) { + p = (char *)memchr(oldBuf, 0x00, length); + if (LIKELY(p == NULL)) { + break; + } + usleep(1); + } + + // now write the old buffer to the trace file on disk + TEMP_FAILURE_RETRY(write(trace_fd, oldBuf, length)); + + // clean buffer for next time + memset(oldBuf, 0x00, TRACE_BUF_SIZ); + } + + LOG("Stopping systrace writer thread ..."); + + return NULL; +} + +#endif // USE_CUSTOM_TRACE_FILE static void _trace_init(void) { - TEMP_FAILURE_RETRY(trace_fd = open(TRACING_FILE, O_WRONLY)); - if (trace_fd == -1) { +#if !USE_CUSTOM_TRACE_FILE + TEMP_FAILURE_RETRY(trace_fd = open(TRACING_PATH, O_WRONLY)); +#else + char path[PAGE_SIZE]; + snprintf(path, sizeof(path), "%s/systrace.txt", HOMEDIR); + + trace_fd = TEMP_FAILURE_RETRY(open(path, OPEN_FLAGS, MODE_FLAGS)); + assert(trace_fd >= 0); + + assert(systrace_thread_id == 0); + int err = TEMP_FAILURE_RETRY(pthread_create(&systrace_thread_id, NULL, (void *)&systrace_thread, (void *)NULL)); + if (err) { + LOG("pthread_create for systrace writer failed!"); + assert(false); + } + + while (!systrace_thread_initialized) { + usleep(FILE_WRITER_USLEEP); + } +#endif + + assert(trace_fd >= 0); + + if (trace_fd < 0) { LOG("Could not open kernel trace file"); } else { LOG("Initialized Linux tracing facility"); } - trace_pid = getpid(); } - static __attribute__((constructor)) void __trace_init(void) { emulator_registerStartupCallback(CTOR_PRIORITY_LATE, &_trace_init); } __attribute__((destructor(255))) static void _trace_shutdown(void) { - if (trace_fd != -1) { - TEMP_FAILURE_RETRY(close(trace_fd)); - trace_fd = -1; + if (trace_fd < 0) { + return; } + int fd = trace_fd; + trace_fd = -1; + TEMP_FAILURE_RETRY(close(fd)); + +#if USE_CUSTOM_TRACE_FILE + systrace_thread_initialized = false; + if (pthread_join(systrace_thread_id, NULL)) { + LOG("OOPS: pthread_join of CPU thread ..."); + } + systrace_thread_id = 0; + + FREE(writeBuf0); + FREE(writeBuf1); + writeHead = NULL; +#endif } -void trace_begin(const char *fmt, ...) { - if (trace_fd == -1) { +void _trace_begin(const char *fmt, ...) { + if (UNLIKELY(trace_fd == -1)) { return; } @@ -64,12 +231,21 @@ void trace_begin(const char *fmt, ...) { va_end(args); char buf[MAX_MSG_LEN] = { 0 }; - size_t length = snprintf(buf, MAX_MSG_LEN, FMT_TRACE_BEGIN, trace_pid, args_buf); + + unsigned long thread_id = (unsigned long)pthread_self(); + +#if USE_CUSTOM_TRACE_FILE + CLOCK_GETTIME(); + size_t length = snprintf(buf, MAX_MSG_LEN, FMT_TRACE_BEGIN, thread_id, secs, '.', usecs, thread_id, args_buf); + _write_trace(buf, length); +#else + size_t length = snprintf(buf, MAX_MSG_LEN, FMT_TRACE_BEGIN, thread_id, args_buf); TEMP_FAILURE_RETRY(write(trace_fd, buf, length)); +#endif } -void trace_begin_count(uint32_t count, const char *fmt, ...) { - if (trace_fd == -1) { +void _trace_begin_count(uint32_t count, const char *fmt, ...) { + if (UNLIKELY(trace_fd == -1)) { return; } @@ -80,20 +256,39 @@ void trace_begin_count(uint32_t count, const char *fmt, ...) { 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); + + unsigned long thread_id = (unsigned long)pthread_self(); + +#if USE_CUSTOM_TRACE_FILE + CLOCK_GETTIME(); + size_t length = snprintf(buf, MAX_MSG_LEN, FMT_TRACE_CBEGIN, thread_id, secs, '.', usecs, thread_id, args_buf, count); + _write_trace(buf, length); +#else + size_t length = snprintf(buf, MAX_MSG_LEN, FMT_TRACE_CBEGIN, thread_id, args_buf, count); TEMP_FAILURE_RETRY(write(trace_fd, buf, length)); +#endif } -void trace_end(void) { - if (trace_fd == -1) { +void _trace_end(void) { + if (UNLIKELY(trace_fd == -1)) { return; } - TEMP_FAILURE_RETRY(write(trace_fd, "E", 1)); + +#if !USE_CUSTOM_TRACE_FILE + TEMP_FAILURE_RETRY(write(trace_fd, FMT_TRACE_END, sizeof(FMT_TRACE_END) - 1)); +#else + char buf[MAX_MSG_LEN]; + buf[0] = '\0'; + + CLOCK_GETTIME(); + unsigned long thread_id = (unsigned long)pthread_self(); + size_t length = snprintf(buf, MAX_MSG_LEN, FMT_TRACE_END, thread_id, secs, '.', usecs); + _write_trace(buf, length); +#endif } void _trace_cleanup(void *token) { - trace_end(); + _trace_end(); } #endif // whole file - diff --git a/src/meta/systrace.h b/src/meta/systrace.h index 2be05290..5123ea04 100644 --- a/src/meta/systrace.h +++ b/src/meta/systrace.h @@ -10,100 +10,102 @@ */ // Function tracing and profiling +// TODO FIXME : migrate toolchain to https://github.com/catapult-project/catapult.git -#ifndef _META_TRACE_H_ -#define _META_TRACE_H_ +#ifndef _META_SYSTRACE_H_ +#define _META_SYSTRACE_H_ -#define TRACE_CPU 0 -#define TRACE_DISK 0 -#define TRACE_AUDIO 0 -#define TRACE_VIDEO 0 -#define TRACE_TOUCH 0 +// Do not enable for official builds! +#define ENABLE_SYSTRACING 0 +#define SYSTRACE_CPU 0 +#define SYSTRACE_DISK 0 +#define SYSTRACE_AUDIO 0 +#define SYSTRACE_VIDEO 0 +#define SYSTRACE_INTERFACE 0 -#if !defined(__linux__) -// TODO FIXME ... implement systrace ... -#else +// WARNING: using a custom tracefile may significantly eat up disk space +#define USE_CUSTOM_TRACE_FILE 1 // If set, will use custom file in $HOME rather than Linux kernel facility 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); +#if ENABLE_SYSTRACING + #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__) +# if SYSTRACE_CPU +# define SCOPE_TRACE_CPU(fmt, ...) _SCOPE_TRACE(__COUNTER__, fmt, ##__VA_ARGS__) # define TRACE_CPU_BEGIN(fmt, ...) _trace_begin(fmt, ##__VA_ARGS__) # define TRACE_CPU_END() _trace_end() +# define TRACE_CPU_MARK(fmt, ...) do { _trace_begin(fmt, ##__VA_ARGS__); _trace_end(); } while (0) # endif -# if TRACE_DISK -# define SCOPE_TRACE_DISK(fmt, ...) SCOPE_TRACE(fmt, ##__VA_ARGS__) +# if SYSTRACE_DISK +# define SCOPE_TRACE_DISK(fmt, ...) _SCOPE_TRACE(__COUNTER__, fmt, ##__VA_ARGS__) # define TRACE_DISK_BEGIN(fmt, ...) _trace_begin(fmt, ##__VA_ARGS__) # define TRACE_DISK_END() _trace_end() +# define TRACE_DISK_MARK(fmt, ...) do { _trace_begin(fmt, ##__VA_ARGS__); _trace_end(); } while (0) # endif -# if TRACE_AUDIO -# define SCOPE_TRACE_AUDIO(fmt, ...) SCOPE_TRACE(fmt, ##__VA_ARGS__) +# if SYSTRACE_AUDIO +# define SCOPE_TRACE_AUDIO(fmt, ...) _SCOPE_TRACE(__COUNTER__, fmt, ##__VA_ARGS__) # define TRACE_AUDIO_BEGIN(fmt, ...) _trace_begin(fmt, ##__VA_ARGS__) # define TRACE_AUDIO_END() _trace_end() +# define TRACE_AUDIO_MARK(fmt, ...) do { _trace_begin(fmt, ##__VA_ARGS__); _trace_end(); } while (0) # endif -# if TRACE_VIDEO -# define SCOPE_TRACE_VIDEO(fmt, ...) SCOPE_TRACE(fmt, ##__VA_ARGS__) +# if SYSTRACE_VIDEO +# define SCOPE_TRACE_VIDEO(fmt, ...) _SCOPE_TRACE(__COUNTER__, fmt, ##__VA_ARGS__) # define TRACE_VIDEO_BEGIN(fmt, ...) _trace_begin(fmt, ##__VA_ARGS__) # define TRACE_VIDEO_END() _trace_end() +# define TRACE_VIDEO_MARK(fmt, ...) do { _trace_begin(fmt, ##__VA_ARGS__); _trace_end(); } while (0) # 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() +# if SYSTRACE_INTERFACE +# define SCOPE_TRACE_INTERFACE(fmt, ...) _SCOPE_TRACE(__COUNTER__, fmt, ##__VA_ARGS__) +# define TRACE_INTERFACE_BEGIN(fmt, ...) _trace_begin(fmt, ##__VA_ARGS__) +# define TRACE_INTERFACE_END() _trace_end() +# define TRACE_INTERFACE_MARK(fmt, ...) do { _trace_begin(fmt, ##__VA_ARGS__); _trace_end(); } while (0) # endif #endif -#endif // __linux__ - -#if !defined(SCOPE_TRACE) -# define SCOPE_TRACE(fmt, ...) -#endif - -#if !TRACE_CPU +#if !SYSTRACE_CPU # define SCOPE_TRACE_CPU(fmt, ...) # define TRACE_CPU_BEGIN(fmt, ...) # define TRACE_CPU_END() +# define TRACE_CPU_MARK(fmt, ...) #endif -#if !TRACE_DISK +#if !SYSTRACE_DISK # define SCOPE_TRACE_DISK(fmt, ...) # define TRACE_DISK_BEGIN(fmt, ...) # define TRACE_DISK_END() +# define TRACE_DISK_MARK(fmt, ...) #endif -#if !TRACE_AUDIO +#if !SYSTRACE_AUDIO # define SCOPE_TRACE_AUDIO(fmt, ...) # define TRACE_AUDIO_BEGIN(fmt, ...) # define TRACE_AUDIO_END() +# define TRACE_AUDIO_MARK(fmt, ...) #endif -#if !TRACE_VIDEO +#if !SYSTRACE_VIDEO # define SCOPE_TRACE_VIDEO(fmt, ...) # define TRACE_VIDEO_BEGIN(fmt, ...) # define TRACE_VIDEO_END() +# define TRACE_VIDEO_MARK(fmt, ...) #endif -#if !TRACE_TOUCH -# define SCOPE_TRACE_TOUCH(fmt, ...) -# define TRACE_TOUCH_BEGIN(fmt, ...) -# define TRACE_TOUCH_END() +#if !SYSTRACE_INTERFACE +# define SCOPE_TRACE_INTERFACE(fmt, ...) +# define TRACE_INTERFACE_BEGIN(fmt, ...) +# define TRACE_INTERFACE_END() +# define TRACE_INTERFACE_MARK(fmt, ...) #endif -#else - #endif // whole file - diff --git a/src/timing.c b/src/timing.c index a94f6ad9..9b312ea2 100644 --- a/src/timing.c +++ b/src/timing.c @@ -278,7 +278,8 @@ cpu_runloop: clock_gettime(CLOCK_MONOTONIC, &t0); do { - SCOPE_TRACE_CPU("CPU mainloop"); + ////SCOPE_TRACE_CPU("CPU mainloop"); + // -LOCK----------------------------------------------------------------------------------------- SAMPLE ti if (UNLIKELY(emul_pause_audio)) { emul_pause_audio = false; @@ -363,7 +364,9 @@ cpu_runloop: speaker_flush(); // play audio + TRACE_CPU_BEGIN("advance scanner"); video_scannerUpdate(); + TRACE_CPU_END(); clock_gettime(CLOCK_MONOTONIC, &tj); pthread_mutex_unlock(&interface_mutex); @@ -409,9 +412,9 @@ cpu_runloop: { deltat.tv_sec = 0; deltat.tv_nsec = sleepfor; - TRACE_CPU_BEGIN("sleep"); + ////TRACE_CPU_BEGIN("sleep"); nanosleep(&deltat, NULL); - TRACE_CPU_END(); + ////TRACE_CPU_END(); } #if DEBUG_TIMING diff --git a/src/video/glnode.c b/src/video/glnode.c index af184eab..d3327d4e 100644 --- a/src/video/glnode.c +++ b/src/video/glnode.c @@ -216,7 +216,7 @@ static void glnode_renderNodes(void) { #if INTERFACE_TOUCH static 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"); + SCOPE_TRACE_INTERFACE("glnode onTouchEvent"); glnode_array_node_s *p = tail; int64_t flags = 0x0; while (p) { diff --git a/src/video/gltouchjoy_joy.c b/src/video/gltouchjoy_joy.c index d5f6781f..c67300c8 100644 --- a/src/video/gltouchjoy_joy.c +++ b/src/video/gltouchjoy_joy.c @@ -82,6 +82,7 @@ static struct timespec *_tap_wait(void) { } static void *_button_tap_delayed_thread(void *dummyptr) { + TRACE_INTERFACE_MARK("_button_tap_delayed_thread ..."); LOG(">>> [DELAYEDTAP] thread start ..."); pthread_mutex_lock(&joys.tapDelayMutex); diff --git a/src/video/video.c b/src/video/video.c index baaf6fd8..cde43c60 100644 --- a/src/video/video.c +++ b/src/video/video.c @@ -224,6 +224,7 @@ void video_setDirty(unsigned long flags) { __sync_fetch_and_or(&dirty, flags); if (flags & A2_DIRTY_FLAG) { ASSERT_ON_CPU_THREAD(); + SCOPE_TRACE_CPU("video_setDirty ..."); // NOTE without knowing any specific information about the nature of the video update, the scanner needs to render 1.X full frames to make sure we've correct rendered the change ... timing_checkpointCycles(); @@ -272,6 +273,7 @@ static void _flushScanline(uint8_t *scanline, unsigned int scanrow, unsigned int } static void _endOfFrame() { + SCOPE_TRACE_CPU("_endOfFrame ..."); assert(cyclesFrameLast >= CYCLES_FRAME); assert(cycles_video_frame >= CYCLES_FRAME); cyclesFrameLast %= CYCLES_FRAME; @@ -345,6 +347,9 @@ void video_scannerUpdate(void) { assert(cycles_video_frame >= cyclesFrameLast); unsigned int cyclesCount = cycles_video_frame - cyclesFrameLast; cyclesCount = (cyclesCount <= cyclesDirty) ? cyclesCount : cyclesDirty; + + SCOPE_TRACE_CPU("video_scannerUpdate : %u", cyclesCount); + for (unsigned int i=0; i 0); // subtract below will not underflow ... const bool isVisible = ((hCount >= CYCLES_VIS_BEGIN) && (vCount < SCANLINES_VBL_BEGIN));