From fb434f09b8486cfd71f7890c1d5bff087b638022 Mon Sep 17 00:00:00 2001 From: xsl Date: Thu, 23 Apr 2026 11:29:18 +0800 Subject: [PATCH 1/2] =?UTF-8?q?=E6=B7=BB=E5=8A=A0=E8=B0=83=E8=AF=95?= =?UTF-8?q?=E6=97=A5=E5=BF=97?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .gitignore | 1 + CMakeLists.txt | 2 + DEBUG_GUIDE.md | 191 ++++++++++++++++++++++++++++++++++ app/src/main/cpp/DebugLog.cpp | 98 +++++++++++++++++ app/src/main/cpp/DebugLog.h | 25 +++++ app/src/main/cpp/main.cpp | 85 ++++++++++++++- vulkan/Application.cpp | 63 ++++++++++- vulkan/FaceApp.cpp | 15 +++ 8 files changed, 477 insertions(+), 3 deletions(-) create mode 100644 DEBUG_GUIDE.md create mode 100644 app/src/main/cpp/DebugLog.cpp create mode 100644 app/src/main/cpp/DebugLog.h diff --git a/.gitignore b/.gitignore index aa724b7..377e1a6 100644 --- a/.gitignore +++ b/.gitignore @@ -12,4 +12,5 @@ /captures .externalNativeBuild .cxx +.idea local.properties diff --git a/CMakeLists.txt b/CMakeLists.txt index 975bf74..1dd9080 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -26,6 +26,8 @@ if(CMAKE_SYSTEM_NAME STREQUAL "Android") add_library(face_sdk SHARED app/src/main/cpp/main.cpp app/src/main/cpp/AndroidOut.cpp + app/src/main/cpp/DebugLog.h + app/src/main/cpp/DebugLog.cpp vulkan/AppBase.h vulkan/AppBase.cpp vulkan/Application.h diff --git a/DEBUG_GUIDE.md b/DEBUG_GUIDE.md new file mode 100644 index 0000000..d50a68e --- /dev/null +++ b/DEBUG_GUIDE.md @@ -0,0 +1,191 @@ +# Face SDK 崩溃调试指南 + +本文档说明如何配合 AI 定位 `libface_sdk.so` 里的崩溃 / 异常。核心思路：**把 Vulkan 每一次异常的上下文写进一个持久日志文件里，崩溃或画面卡住后把这份文件发给 AI 分析。** + +--- + +## 一、已经加好的东西（不需要你做什么） + +### 1. `DebugLog` 模块（`app/src/main/cpp/DebugLog.{h,cpp}`） + +- 线程安全； +- 每条日志带**时间戳 + 线程 ID（tid）**； +- 写到 App **私有目录下的文件** —— 不会被 logcat 自动清掉； +- 每写一行 `fflush`，进程挂了也不丢最后几行； +- 文件大小超过 2MB 自动滚动到 `.old`； +- 同步把日志镜像到 logcat，tag 是 `FACE_DBG`。 + +### 2. 打点位置 + +| 位置 | 打点内容 | 用途 | +|---|---|---| +| `android_main` 启动 | pid、tid、日志文件绝对路径 | 每次启动一条，作为分段锚点 | +| 渲染循环心跳 | 每 600 帧一条：`frame=X exceptions_so_far=Y` | 判断启动多久后崩溃 / 异常持续性 | +| `try/catch` 兜底 | 首 10 次异常每次都打，之后每 120 次打一次 | **Vulkan 异常不会再让进程硬崩**，留住现场 | +| `handle_cmd` | 每个 `APP_CMD_*` 事件（尤其 `INIT_WINDOW`/`TERM_WINDOW`/`CONFIG_CHANGED`） | 旋转 / 切后台 / 锁屏场景的时间线 | +| `FaceApp::initVulkan` 入/出口 | 调用次数、`_applicationInited` / `_faceAppInited` / `_sceondInited` 状态 | 判断是否被多次重复调用 | +| `processImageNative` / `passDataToNative` | 每 300 次调用打一条 tid | 验证"Java 两个回调在不同线程并发调 Vulkan"假设 | +| `Application::drawFrame` 里的 4 次 Vulkan 调用 | 非 `VK_SUCCESS` 时打印数值 + 字符串名（例如 `-4 (VK_ERROR_DEVICE_LOST)`） | **最关键的证据** | + +### 3. 关键行为变化 + +**⚠️ 现在 `drawFrame` 里 Vulkan 抛出的异常会被 `try/catch` 吃掉 —— App 不会再因为这类问题硬崩溃。** + +- 好处：你能继续跑、继续复现、日志一直在写； +- 代价：出问题时表现从"崩溃"变成"**画面卡住 / 黑屏 / 不再更新**"。 +- 如果想暂时回到硬崩行为：把 `app/src/main/cpp/main.cpp` 里那段 `try { g_Application->drawFrame(...); } catch (...) { ... }` 改回直接 `g_Application->drawFrame(frameTime);` 即可。 + +--- + +## 二、怎么把日志文件取出来 + +### 方式 A：`run-as`（推荐，不需要 root） + +```bash +adb shell "run-as com.inewme.uvmirror cat files/face_sdk_debug.log" > face_sdk_debug.log +adb shell "run-as com.inewme.uvmirror cat files/face_sdk_debug.log.old" > face_sdk_debug.log.old +``` + +> `.old` 只有文件滚动过一次才存在，没有可以忽略错误。 + +### 方式 B：直接看 logcat（实时） + +```bash +adb logcat -s FACE_DBG +``` + +和文件内容基本一致。跑较久的话还是文件更可靠。 + +### 方式 C：从 App 里拿路径 + +启动后 `FACE_DBG` 第一条日志长这样： + +``` +[10:12:03.041][tid=12345] android_main start, pid=23456 tid=12345, logPath=/data/user/0/com.inewme.uvmirror/files/face_sdk_debug.log +``` + +照这个路径走就对了。 + +--- + +## 三、你现在要做的事（B 方案：两种场景都复现一次） + +### 场景 1：旋转崩溃（已确认必现） + +1. 打开 App，等初始化完成（画面能看到人脸渲染）。 +2. **旋转一次屏幕**。 +3. 等 3~5 秒让日志写进去。 +4. 取 `face_sdk_debug.log`，**不要清文件**，继续场景 2。 + +期望看到的关键行： +``` +>> handle_cmd APP_CMD_TERM_WINDOW(...) +>> handle_cmd APP_CMD_INIT_WINDOW(...) +FaceApp::initVulkan enter, call#2 ... +drawFrame[NNN] vkAcquireNextImageKHR -> ??? (...) +!!! drawFrame std::exception (frame=NNN count=M): failed to ... +``` + +注意里面那个 `???` —— 这是整件事的核心证据。 + +### 场景 2：长时间运行崩溃（之前那个 10 分钟左右的） + +**不要退出 App，接着跑**。现在即使旋转触发了异常，进程没死，我们希望看后续会不会再出另一种 VkResult： + +1. 尽量不操作（不切后台、不旋转、不锁屏，让 App 持续渲染）。 +2. 连续跑 **15~20 分钟**，观察是否复现之前的"无外部事件崩溃"。 +3. 复现后（或稳定 20 分钟未复现也行），再取一次 `face_sdk_debug.log`（这次会覆盖场景 1 的那份，所以务必**先把场景 1 的单独保存好**）。 + +期望看到的关键行（如果真的是 DEVICE_LOST）： +``` +drawFrame[NNN] vkQueueSubmit -> -4 (VK_ERROR_DEVICE_LOST) ... +``` +或者某个 Vulkan 调用返回其他错误码。 + +### 辅助信息（手边有就顺便记一下） + +| 项 | 为什么要 | +|---|---| +| 机型 + Android 版本 | GPU 驱动差异；Adreno / Mali / Xclipse 表现差别大 | +| 复现时手机是不是很烫 | 排查 GPU 温控 / thermal throttling | +| 旋转时是"横屏 → 竖屏"还是"竖屏 → 横屏" / 多次连续旋转？ | 某些机型一次 vs 多次触发行为不同 | +| 10 分钟崩溃时 App 在做什么（有在切换 motion 吗？） | 帮助排除 `changeMotionList` 相关路径 | + +--- + +## 四、发给 AI 的时候包含什么 + +最小集： + +1. `face_sdk_debug.log`（场景 1 旋转那份） +2. `face_sdk_debug.log`（场景 2 长跑那份） +3. 如果文件很大，**完整发**比截断发强（AI 主要关心最后几千行） +4. 一句话说明这份日志对应场景 1 还是场景 2，是否复现了 + +不需要的： + +- logcat 完整 dump（体积太大且大多无关，除非 AI 主动问特定 tag） +- 录屏 +- 源代码（AI 已经能看到仓库） + +--- + +## 五、当前未解决的假设，等日志验证 + +| 假设 | 对应 VkResult | 修法 | +|---|---|---| +| 旋转导致 surface 失效未处理 | `VK_ERROR_OUT_OF_DATE_KHR` (-1000001004) 或 `VK_ERROR_SURFACE_LOST_KHR` (-1000000000) 或 `VK_SUBOPTIMAL_KHR` (1000001003) | 实现 `APP_CMD_TERM_WINDOW` 销毁流程 + swapchain 重建 | +| Java 多线程并发提交 graphicsQueue 导致 GPU 长时间后挂 | `VK_ERROR_DEVICE_LOST` (-4)，且 `processImageNative` / `passDataToNative` 日志里 tid 不同 | 给所有 `vkQueueSubmit`/`vkQueuePresentKHR` 加全局 queue mutex | +| 驱动 bug / 温度导致 GPU hang | `VK_ERROR_DEVICE_LOST` (-4)，单线程也出 | 捕获并尝试重建 device，或上报给机型厂商 | +| 资源累积泄漏 | `VK_ERROR_OUT_OF_DEVICE_MEMORY` (-2) 或 `VK_ERROR_TOO_MANY_OBJECTS` | 排查 `beginSingleTimeCommands`/`processWithVulkan` 路径 | + +--- + +## 六、日志样例（便于你确认打印是否正常） + +正常启动应该看到： +``` +========== DebugLog opened @ 2026-04-23 14:05:12 (pid=12345) ========== +[14:05:12.019][tid=12345] android_main start, pid=12345 tid=12345, logPath=/data/user/0/com.inewme.uvmirror/files/face_sdk_debug.log +[14:05:12.155][tid=12345] >> handle_cmd APP_CMD_START(10) tid=12345 +[14:05:12.155][tid=12345] << handle_cmd APP_CMD_START done +[14:05:12.210][tid=12345] >> handle_cmd APP_CMD_INIT_WINDOW(1) tid=12345 +[14:05:12.210][tid=12345] handle_cmd APP_CMD_INIT_WINDOW: calling initVulkan() +[14:05:12.210][tid=12345] FaceApp::initVulkan enter, call#1 _applicationInited=0 _faceAppInited=0 _secondfaceAppInited=0 +[14:05:13.420][tid=12345] FaceApp::initVulkan exit, call#1 _applicationInited=1 _faceAppInited=1 _secondfaceAppInited=1 +[14:05:13.420][tid=12345] handle_cmd APP_CMD_INIT_WINDOW: initVulkan() returned, isInited=1 +[14:05:13.421][tid=12345] << handle_cmd APP_CMD_INIT_WINDOW done +[14:05:14.005][tid=67890] processImageNative #1 tid=67890 w=480 h=480 +[14:05:14.008][tid=67891] passDataToNative #1 tid=67891 point_count=468 w=480 h=480 +[14:05:35.200][tid=12345] heartbeat: frame=600 exceptions_so_far=0 +``` + +旋转时如果触发异常应该看到： +``` +[14:06:10.112][tid=12345] >> handle_cmd APP_CMD_CONFIG_CHANGED(8) tid=12345 +[14:06:10.113][tid=12345] >> handle_cmd APP_CMD_TERM_WINDOW(2) tid=12345 +[14:06:10.113][tid=12345] handle_cmd APP_CMD_TERM_WINDOW: (no handler yet, ...) +[14:06:10.113][tid=12345] << handle_cmd APP_CMD_TERM_WINDOW done +[14:06:10.250][tid=12345] >> handle_cmd APP_CMD_INIT_WINDOW(1) tid=12345 +[14:06:10.250][tid=12345] FaceApp::initVulkan enter, call#2 _applicationInited=1 _faceAppInited=1 _secondfaceAppInited=0 +[14:06:10.250][tid=12345] FaceApp::initVulkan exit, call#2 _applicationInited=1 _faceAppInited=1 _secondfaceAppInited=1 +[14:06:10.280][tid=12345] drawFrame[1234] vkAcquireNextImageKHR -> -1000001004 (VK_ERROR_OUT_OF_DATE_KHR) currentFrame=0 +[14:06:10.280][tid=12345] !!! drawFrame std::exception (frame=1234 count=1): failed to acquire swap chain image! +``` + +**只要日志里能看到 `vkXxxKHR -> <数值> (<名字>)` 这一行，诊断就成立了。** + +--- + +## 七、文件清单（仅供参考，日常不用动） + +``` +app/src/main/cpp/ + DebugLog.h 新增 + DebugLog.cpp 新增 + main.cpp 改：日志初始化 / 心跳 / try-catch / cmd 日志 / JNI tid +vulkan/ + Application.cpp 改：drawFrame 4 处 VkResult 日志 + VkResultStr + FaceApp.cpp 改：initVulkan 入/出口日志 +CMakeLists.txt 改：加入 DebugLog.cpp 到 Android 构建 +``` diff --git a/app/src/main/cpp/DebugLog.cpp b/app/src/main/cpp/DebugLog.cpp new file mode 100644 index 0000000..0815aac --- /dev/null +++ b/app/src/main/cpp/DebugLog.cpp @@ -0,0 +1,98 @@ +#include "DebugLog.h" + +#include +#include +#include +#include + +#include +#include +#include +#include + +namespace { + +std::mutex g_mtx; +FILE* g_fp = nullptr; +std::string g_path; +constexpr size_t kMaxSize = 2 * 1024 * 1024; // 2 MB before rotation + +pid_t currentTid() { + return static_cast(syscall(SYS_gettid)); +} + +} // namespace + +namespace DebugLog { + +void init(const char* internalDataPath) { + std::lock_guard lk(g_mtx); + if (g_fp) { + return; // already initialized + } + + const char* base = (internalDataPath && *internalDataPath) ? internalDataPath : "/data/local/tmp"; + g_path = std::string(base) + "/face_sdk_debug.log"; + + // Rotate once if current file is too large. + struct stat st{}; + if (stat(g_path.c_str(), &st) == 0 && static_cast(st.st_size) > kMaxSize) { + std::string backup = g_path + ".old"; + std::remove(backup.c_str()); + std::rename(g_path.c_str(), backup.c_str()); + } + + g_fp = std::fopen(g_path.c_str(), "a"); + if (g_fp) { + time_t now = time(nullptr); + struct tm tm_info{}; + localtime_r(&now, &tm_info); + char tbuf[64]; + strftime(tbuf, sizeof(tbuf), "%Y-%m-%d %H:%M:%S", &tm_info); + std::fprintf(g_fp, + "\n========== DebugLog opened @ %s (pid=%d) ==========\n", + tbuf, getpid()); + std::fflush(g_fp); + } + + __android_log_print(ANDROID_LOG_INFO, "FACE_DBG", + "DebugLog file path: %s", g_path.c_str()); +} + +void log(const char* fmt, ...) { + char buf[1024]; + va_list ap; + va_start(ap, fmt); + int n = std::vsnprintf(buf, sizeof(buf), fmt, ap); + va_end(ap); + if (n < 0) return; + + pid_t tid = currentTid(); + + timespec ts{}; + clock_gettime(CLOCK_REALTIME, &ts); + struct tm tm_info{}; + localtime_r(&ts.tv_sec, &tm_info); + char timebuf[32]; + strftime(timebuf, sizeof(timebuf), "%H:%M:%S", &tm_info); + + std::lock_guard lk(g_mtx); + if (g_fp) { + std::fprintf(g_fp, "[%s.%03ld][tid=%d] %s\n", + timebuf, ts.tv_nsec / 1000000, tid, buf); + std::fflush(g_fp); + } + __android_log_print(ANDROID_LOG_INFO, "FACE_DBG", "[tid=%d] %s", tid, buf); +} + +void flush() { + std::lock_guard lk(g_mtx); + if (g_fp) std::fflush(g_fp); +} + +std::string getLogPath() { + std::lock_guard lk(g_mtx); + return g_path; +} + +} // namespace DebugLog diff --git a/app/src/main/cpp/DebugLog.h b/app/src/main/cpp/DebugLog.h new file mode 100644 index 0000000..49ce238 --- /dev/null +++ b/app/src/main/cpp/DebugLog.h @@ -0,0 +1,25 @@ +#ifndef FACE_SDK_DEBUGLOG_H +#define FACE_SDK_DEBUGLOG_H + +#include + +namespace DebugLog { + +// Call once (e.g. in android_main) with android_app->activity->internalDataPath. +// Safe to call multiple times; subsequent calls are no-ops. +void init(const char* internalDataPath); + +// Thread-safe. Also mirrored to logcat with tag "FACE_DBG". +// Every line is prefixed with timestamp + thread id and flushed to disk immediately, +// so even a hard crash will preserve the tail. +void log(const char* fmt, ...) __attribute__((format(printf, 1, 2))); + +// Force flush to disk. +void flush(); + +// Absolute path of the log file (valid after init()). +std::string getLogPath(); + +} // namespace DebugLog + +#endif // FACE_SDK_DEBUGLOG_H diff --git a/app/src/main/cpp/main.cpp b/app/src/main/cpp/main.cpp index 54d346b..88ce0cd 100644 --- a/app/src/main/cpp/main.cpp +++ b/app/src/main/cpp/main.cpp @@ -3,12 +3,43 @@ #include #include #include "AndroidOut.h" +#include "DebugLog.h" #include "FaceApp.h" #include +#include +#include +#include #include #include using namespace std; + +static inline pid_t dbg_tid() { + return static_cast(syscall(SYS_gettid)); +} + +static const char* appCmdName(int32_t cmd) { + switch (cmd) { + case APP_CMD_INPUT_CHANGED: return "APP_CMD_INPUT_CHANGED"; + case APP_CMD_INIT_WINDOW: return "APP_CMD_INIT_WINDOW"; + case APP_CMD_TERM_WINDOW: return "APP_CMD_TERM_WINDOW"; + case APP_CMD_WINDOW_RESIZED: return "APP_CMD_WINDOW_RESIZED"; + case APP_CMD_WINDOW_REDRAW_NEEDED: return "APP_CMD_WINDOW_REDRAW_NEEDED"; + case APP_CMD_CONTENT_RECT_CHANGED: return "APP_CMD_CONTENT_RECT_CHANGED"; + case APP_CMD_GAINED_FOCUS: return "APP_CMD_GAINED_FOCUS"; + case APP_CMD_LOST_FOCUS: return "APP_CMD_LOST_FOCUS"; + case APP_CMD_CONFIG_CHANGED: return "APP_CMD_CONFIG_CHANGED"; + case APP_CMD_LOW_MEMORY: return "APP_CMD_LOW_MEMORY"; + case APP_CMD_START: return "APP_CMD_START"; + case APP_CMD_RESUME: return "APP_CMD_RESUME"; + case APP_CMD_SAVE_STATE: return "APP_CMD_SAVE_STATE"; + case APP_CMD_PAUSE: return "APP_CMD_PAUSE"; + case APP_CMD_STOP: return "APP_CMD_STOP"; + case APP_CMD_DESTROY: return "APP_CMD_DESTROY"; + default: return "APP_CMD_???"; + } +} + extern "C" { android_app* g_android_app = nullptr; @@ -19,23 +50,32 @@ jobject g_callback = nullptr; jobject g_callbackAnimationFinished = nullptr; void handle_cmd(android_app *pApp, int32_t cmd) { + DebugLog::log(">> handle_cmd %s(%d) tid=%d", appCmdName(cmd), (int)cmd, dbg_tid()); switch (cmd) { case APP_CMD_INIT_WINDOW: aout << "APP_CMD_INIT_WINDOW" << std::endl; + DebugLog::log("handle_cmd APP_CMD_INIT_WINDOW: calling initVulkan()"); g_Application->initVulkan(); + DebugLog::log("handle_cmd APP_CMD_INIT_WINDOW: initVulkan() returned, isInited=%d", + (int)g_Application->isInited()); break; case APP_CMD_TERM_WINDOW: aout << "APP_CMD_TERM_WINDOW" << std::endl; + DebugLog::log("handle_cmd APP_CMD_TERM_WINDOW: (no handler yet, swapChain/surface still point to dead ANativeWindow)"); break; default: break; } + DebugLog::log("<< handle_cmd %s done", appCmdName(cmd)); } const int ArgLen = 128*1024; char g_InitArgString[ArgLen] = {0}; void android_main(struct android_app *pApp) { + DebugLog::init(pApp->activity->internalDataPath); + DebugLog::log("android_main start, pid=%d tid=%d, logPath=%s", + getpid(), dbg_tid(), DebugLog::getLogPath().c_str()); aout << "Welcome to android_main" << std::endl; g_android_app = pApp; g_assetManager = pApp->activity->assetManager; @@ -80,7 +120,38 @@ void android_main(struct android_app *pApp) { { auto frameTime = (start_time - _lastDrawFrameTime); _lastDrawFrameTime = chrono::duration_cast(chrono::system_clock::now().time_since_epoch()).count(); - g_Application->drawFrame(frameTime); + + static uint64_t s_frameIdx = 0; + static uint64_t s_excCount = 0; + static uint64_t s_lastLoggedExc = 0; + ++s_frameIdx; + if (s_frameIdx % 600 == 0) { + DebugLog::log("heartbeat: frame=%llu exceptions_so_far=%llu", + (unsigned long long)s_frameIdx, + (unsigned long long)s_excCount); + } + + try { + g_Application->drawFrame(frameTime); + } catch (const std::exception& e) { + ++s_excCount; + // Log first 10 exceptions verbosely, then at most one per 120 swallowed. + if (s_excCount <= 10 || (s_excCount - s_lastLoggedExc) >= 120) { + DebugLog::log("!!! drawFrame std::exception (frame=%llu count=%llu): %s", + (unsigned long long)s_frameIdx, + (unsigned long long)s_excCount, + e.what()); + s_lastLoggedExc = s_excCount; + } + } catch (...) { + ++s_excCount; + if (s_excCount <= 10 || (s_excCount - s_lastLoggedExc) >= 120) { + DebugLog::log("!!! drawFrame unknown exception (frame=%llu count=%llu)", + (unsigned long long)s_frameIdx, + (unsigned long long)s_excCount); + s_lastLoggedExc = s_excCount; + } + } } auto end_time = chrono::duration_cast(chrono::system_clock::now().time_since_epoch()).count(); auto frameTime = end_time - last_update_time; @@ -114,6 +185,12 @@ Java_com_hmwl_face_1sdk_FaceActivity_processImageNative(JNIEnv *env, jobject thi jint width, jint height, jint format, jint row_stride, jint pixel_stride, jint rotation) { + static std::atomic s_imgCount{0}; + uint64_t n = s_imgCount.fetch_add(1) + 1; + if (n == 1 || n % 300 == 0) { + DebugLog::log("processImageNative #%llu tid=%d w=%d h=%d", + (unsigned long long)n, dbg_tid(), width, height); + } // TODO: implement processImageNative() uint8_t* imageData = static_cast(env->GetDirectBufferAddress(buffer)); jlong capacity = env->GetDirectBufferCapacity(buffer); @@ -130,6 +207,12 @@ extern "C" JNIEXPORT void JNICALL Java_com_hmwl_face_1sdk_FaceActivity_passDataToNative(JNIEnv *env, jobject thiz, jobject buffer, jint point_count, jint width, jint height) { + static std::atomic s_ptCount{0}; + uint64_t n = s_ptCount.fetch_add(1) + 1; + if (n == 1 || n % 300 == 0) { + DebugLog::log("passDataToNative #%llu tid=%d point_count=%d w=%d h=%d", + (unsigned long long)n, dbg_tid(), point_count, width, height); + } // TODO: implement passDataToNative() float* pos = static_cast(env->GetDirectBufferAddress(buffer)); diff --git a/vulkan/Application.cpp b/vulkan/Application.cpp index 3eb1719..f9d6170 100644 --- a/vulkan/Application.cpp +++ b/vulkan/Application.cpp @@ -9,8 +9,47 @@ #include #include #include "../app/src/main/cpp/AndroidOut.h" + #include "../app/src/main/cpp/DebugLog.h" #endif +#ifdef _WIN32 +#define FACE_DBG_LOG(...) ((void)0) +#else +#define FACE_DBG_LOG(...) DebugLog::log(__VA_ARGS__) +#endif + +static const char* VkResultStr(VkResult r) { + switch (r) { + case VK_SUCCESS: return "VK_SUCCESS"; + case VK_NOT_READY: return "VK_NOT_READY"; + case VK_TIMEOUT: return "VK_TIMEOUT"; + case VK_EVENT_SET: return "VK_EVENT_SET"; + case VK_EVENT_RESET: return "VK_EVENT_RESET"; + case VK_INCOMPLETE: return "VK_INCOMPLETE"; + case VK_SUBOPTIMAL_KHR: return "VK_SUBOPTIMAL_KHR"; + case VK_ERROR_OUT_OF_HOST_MEMORY: return "VK_ERROR_OUT_OF_HOST_MEMORY"; + case VK_ERROR_OUT_OF_DEVICE_MEMORY: return "VK_ERROR_OUT_OF_DEVICE_MEMORY"; + case VK_ERROR_INITIALIZATION_FAILED: return "VK_ERROR_INITIALIZATION_FAILED"; + case VK_ERROR_DEVICE_LOST: return "VK_ERROR_DEVICE_LOST"; + case VK_ERROR_MEMORY_MAP_FAILED: return "VK_ERROR_MEMORY_MAP_FAILED"; + case VK_ERROR_LAYER_NOT_PRESENT: return "VK_ERROR_LAYER_NOT_PRESENT"; + case VK_ERROR_EXTENSION_NOT_PRESENT: return "VK_ERROR_EXTENSION_NOT_PRESENT"; + case VK_ERROR_FEATURE_NOT_PRESENT: return "VK_ERROR_FEATURE_NOT_PRESENT"; + case VK_ERROR_INCOMPATIBLE_DRIVER: return "VK_ERROR_INCOMPATIBLE_DRIVER"; + case VK_ERROR_TOO_MANY_OBJECTS: return "VK_ERROR_TOO_MANY_OBJECTS"; + case VK_ERROR_FORMAT_NOT_SUPPORTED: return "VK_ERROR_FORMAT_NOT_SUPPORTED"; + case VK_ERROR_FRAGMENTED_POOL: return "VK_ERROR_FRAGMENTED_POOL"; + case VK_ERROR_OUT_OF_DATE_KHR: return "VK_ERROR_OUT_OF_DATE_KHR"; + case VK_ERROR_SURFACE_LOST_KHR: return "VK_ERROR_SURFACE_LOST_KHR"; + case VK_ERROR_NATIVE_WINDOW_IN_USE_KHR: return "VK_ERROR_NATIVE_WINDOW_IN_USE_KHR"; + case VK_ERROR_OUT_OF_POOL_MEMORY: return "VK_ERROR_OUT_OF_POOL_MEMORY"; + case VK_ERROR_INVALID_EXTERNAL_HANDLE: return "VK_ERROR_INVALID_EXTERNAL_HANDLE"; + case VK_ERROR_FRAGMENTATION: return "VK_ERROR_FRAGMENTATION"; + case VK_ERROR_UNKNOWN: return "VK_ERROR_UNKNOWN"; + default: return "VK_UNMAPPED_VALUE"; + } +} + void Application::initWindow() @@ -545,13 +584,24 @@ void Application::render(VkCommandBuffer commandBuffer, long long frameTime) void Application::drawFrame(long long frameTime) { + static uint64_t s_drawFrameCount = 0; + ++s_drawFrameCount; + // 1. 等待前一帧完成 - vkWaitForFences(device, 1, &inFlightFences[currentFrame], VK_TRUE, UINT64_MAX); + VkResult waitRes = vkWaitForFences(device, 1, &inFlightFences[currentFrame], VK_TRUE, UINT64_MAX); + if (waitRes != VK_SUCCESS) { + FACE_DBG_LOG("drawFrame[%llu] vkWaitForFences -> %d (%s) currentFrame=%u", + (unsigned long long)s_drawFrameCount, + (int)waitRes, VkResultStr(waitRes), currentFrame); + } // 2. 获取交换链图像 uint32_t imageIndex; VkResult result = vkAcquireNextImageKHR(device, swapChain, UINT64_MAX, imageAvailableSemaphores[currentFrame], VK_NULL_HANDLE, &imageIndex); if (result != VK_SUCCESS) { + FACE_DBG_LOG("drawFrame[%llu] vkAcquireNextImageKHR -> %d (%s) currentFrame=%u", + (unsigned long long)s_drawFrameCount, + (int)result, VkResultStr(result), currentFrame); throw std::runtime_error("failed to acquire swap chain image!"); } @@ -582,7 +632,12 @@ void Application::drawFrame(long long frameTime) submitInfo.signalSemaphoreCount = 1; submitInfo.pSignalSemaphores = signalSemaphores; - if (vkQueueSubmit(graphicsQueue, 1, &submitInfo, inFlightFences[currentFrame]) != VK_SUCCESS) { + VkResult submitRes = vkQueueSubmit(graphicsQueue, 1, &submitInfo, inFlightFences[currentFrame]); + if (submitRes != VK_SUCCESS) { + FACE_DBG_LOG("drawFrame[%llu] vkQueueSubmit -> %d (%s) currentFrame=%u imageIndex=%u", + (unsigned long long)s_drawFrameCount, + (int)submitRes, VkResultStr(submitRes), + currentFrame, imageIndex); throw std::runtime_error("failed to submit draw command buffer!"); } // 7. 呈现图像 @@ -597,6 +652,10 @@ void Application::drawFrame(long long frameTime) result = vkQueuePresentKHR(presentQueue, &presentInfo); if (result != VK_SUCCESS) { + FACE_DBG_LOG("drawFrame[%llu] vkQueuePresentKHR -> %d (%s) currentFrame=%u imageIndex=%u", + (unsigned long long)s_drawFrameCount, + (int)result, VkResultStr(result), + currentFrame, imageIndex); throw std::runtime_error("failed to present swap chain image!"); } diff --git a/vulkan/FaceApp.cpp b/vulkan/FaceApp.cpp index 620d04f..56e45eb 100644 --- a/vulkan/FaceApp.cpp +++ b/vulkan/FaceApp.cpp @@ -6,6 +6,13 @@ #include #include +#ifndef _WIN32 +#include "../app/src/main/cpp/DebugLog.h" +#define FACE_DBG_LOG(...) DebugLog::log(__VA_ARGS__) +#else +#define FACE_DBG_LOG(...) ((void)0) +#endif + FaceApp* FaceApp::faceIns = nullptr; @@ -772,6 +779,11 @@ void FaceApp::createVmaAllocator() void FaceApp::initVulkan() { + static int s_initVulkanCallCount = 0; + ++s_initVulkanCallCount; + FACE_DBG_LOG("FaceApp::initVulkan enter, call#%d _applicationInited=%d _faceAppInited=%d _secondfaceAppInited=%d", + s_initVulkanCallCount, (int)_applicationInited, (int)_faceAppInited, (int)_secondfaceAppInited); + Application::initVulkan(); if (!_faceAppInited) @@ -839,6 +851,9 @@ void FaceApp::initVulkan() _playMotion = true; _secondfaceAppInited = true; } + + FACE_DBG_LOG("FaceApp::initVulkan exit, call#%d _applicationInited=%d _faceAppInited=%d _secondfaceAppInited=%d", + s_initVulkanCallCount, (int)_applicationInited, (int)_faceAppInited, (int)_secondfaceAppInited); } void FaceApp::clearnSecondFaceApp() From 27b70758189d6932f86dca4b5b6953f0fdcfdf2a Mon Sep 17 00:00:00 2001 From: xiangsilian Date: Thu, 23 Apr 2026 22:18:22 +0800 Subject: [PATCH 2/2] fix bug and add log --- app/src/main/cpp/DebugLog.cpp | 91 ++++++++++++++++++++++---- app/src/main/cpp/DebugLog.h | 8 +++ app/src/main/cpp/main.cpp | 55 +++++++++------- vulkan/Application.cpp | 119 ++++++++++++++++++++++++++++++++-- vulkan/Application.h | 11 ++++ vulkan/FaceApp.cpp | 72 +++++++++++++++++++- vulkan/FaceApp.h | 11 ++++ 7 files changed, 327 insertions(+), 40 deletions(-) diff --git a/app/src/main/cpp/DebugLog.cpp b/app/src/main/cpp/DebugLog.cpp index 0815aac..c24881f 100644 --- a/app/src/main/cpp/DebugLog.cpp +++ b/app/src/main/cpp/DebugLog.cpp @@ -8,7 +8,10 @@ #include #include #include +#include #include +#include +#include namespace { @@ -17,10 +20,43 @@ FILE* g_fp = nullptr; std::string g_path; constexpr size_t kMaxSize = 2 * 1024 * 1024; // 2 MB before rotation +// Throttle bookkeeping: one slot per distinct key passed to log_throttled(). +struct ThrottleSlot { + int64_t last_emit_ms = 0; // when we last actually wrote a line for this key + uint32_t suppressed = 0; // number of calls swallowed since last_emit_ms +}; +std::unordered_map g_throttle; +constexpr int64_t kThrottleWindowMs = 2000; // 2 seconds + pid_t currentTid() { return static_cast(syscall(SYS_gettid)); } +int64_t nowMs() { + timespec ts{}; + clock_gettime(CLOCK_MONOTONIC, &ts); + return static_cast(ts.tv_sec) * 1000 + ts.tv_nsec / 1000000; +} + +// Assumes g_mtx is held. Writes a single pre-formatted line to disk + logcat. +void writeLineLocked(const char* body) { + pid_t tid = currentTid(); + + timespec ts{}; + clock_gettime(CLOCK_REALTIME, &ts); + struct tm tm_info{}; + localtime_r(&ts.tv_sec, &tm_info); + char timebuf[32]; + strftime(timebuf, sizeof(timebuf), "%H:%M:%S", &tm_info); + + if (g_fp) { + std::fprintf(g_fp, "[%s.%03ld][tid=%d] %s\n", + timebuf, ts.tv_nsec / 1000000, tid, body); + std::fflush(g_fp); + } + __android_log_print(ANDROID_LOG_INFO, "FACE_DBG", "[tid=%d] %s", tid, body); +} + } // namespace namespace DebugLog { @@ -67,22 +103,53 @@ void log(const char* fmt, ...) { va_end(ap); if (n < 0) return; - pid_t tid = currentTid(); + std::lock_guard lk(g_mtx); + writeLineLocked(buf); +} - timespec ts{}; - clock_gettime(CLOCK_REALTIME, &ts); - struct tm tm_info{}; - localtime_r(&ts.tv_sec, &tm_info); - char timebuf[32]; - strftime(timebuf, sizeof(timebuf), "%H:%M:%S", &tm_info); +void log_throttled(const char* key, const char* fmt, ...) { + char buf[1024]; + va_list ap; + va_start(ap, fmt); + int n = std::vsnprintf(buf, sizeof(buf), fmt, ap); + va_end(ap); + if (n < 0) return; + + const char* k = key ? key : ""; + int64_t now = nowMs(); std::lock_guard lk(g_mtx); - if (g_fp) { - std::fprintf(g_fp, "[%s.%03ld][tid=%d] %s\n", - timebuf, ts.tv_nsec / 1000000, tid, buf); - std::fflush(g_fp); + auto it = g_throttle.find(k); + if (it == g_throttle.end()) { + // First time we see this key -> always log. + ThrottleSlot slot; + slot.last_emit_ms = now; + slot.suppressed = 0; + g_throttle.emplace(k, slot); + writeLineLocked(buf); + return; } - __android_log_print(ANDROID_LOG_INFO, "FACE_DBG", "[tid=%d] %s", tid, buf); + + ThrottleSlot& slot = it->second; + int64_t elapsed = now - slot.last_emit_ms; + if (elapsed < kThrottleWindowMs) { + // Still inside the 2s window -> swallow. + ++slot.suppressed; + return; + } + + // Window elapsed: emit the line, annotated with how many we swallowed. + if (slot.suppressed > 0) { + char annotated[1200]; + std::snprintf(annotated, sizeof(annotated), + "%s (repeated %u times in last %lldms, key=%s)", + buf, slot.suppressed, (long long)elapsed, k); + writeLineLocked(annotated); + } else { + writeLineLocked(buf); + } + slot.last_emit_ms = now; + slot.suppressed = 0; } void flush() { diff --git a/app/src/main/cpp/DebugLog.h b/app/src/main/cpp/DebugLog.h index 49ce238..6691588 100644 --- a/app/src/main/cpp/DebugLog.h +++ b/app/src/main/cpp/DebugLog.h @@ -14,6 +14,14 @@ void init(const char* internalDataPath); // so even a hard crash will preserve the tail. void log(const char* fmt, ...) __attribute__((format(printf, 1, 2))); +// Throttled variant keyed by a caller-supplied string. +// - The first call with a given key is always written. +// - Subsequent calls with the same key within 2 seconds are suppressed. +// - When the throttle window elapses, the next matching call is written with a +// "(repeated N times in last Xms)" suffix describing the suppressed ones. +// Use stable, short keys (e.g. "drawFrame.acquire", "drawFrame.present"). +void log_throttled(const char* key, const char* fmt, ...) __attribute__((format(printf, 2, 3))); + // Force flush to disk. void flush(); diff --git a/app/src/main/cpp/main.cpp b/app/src/main/cpp/main.cpp index 88ce0cd..7a0bc36 100644 --- a/app/src/main/cpp/main.cpp +++ b/app/src/main/cpp/main.cpp @@ -20,7 +20,6 @@ static inline pid_t dbg_tid() { static const char* appCmdName(int32_t cmd) { switch (cmd) { - case APP_CMD_INPUT_CHANGED: return "APP_CMD_INPUT_CHANGED"; case APP_CMD_INIT_WINDOW: return "APP_CMD_INIT_WINDOW"; case APP_CMD_TERM_WINDOW: return "APP_CMD_TERM_WINDOW"; case APP_CMD_WINDOW_RESIZED: return "APP_CMD_WINDOW_RESIZED"; @@ -54,14 +53,18 @@ void handle_cmd(android_app *pApp, int32_t cmd) { switch (cmd) { case APP_CMD_INIT_WINDOW: aout << "APP_CMD_INIT_WINDOW" << std::endl; - DebugLog::log("handle_cmd APP_CMD_INIT_WINDOW: calling initVulkan()"); - g_Application->initVulkan(); - DebugLog::log("handle_cmd APP_CMD_INIT_WINDOW: initVulkan() returned, isInited=%d", + DebugLog::log("handle_cmd APP_CMD_INIT_WINDOW: calling onWindowInit()"); + g_Application->onWindowInit(); + DebugLog::log("handle_cmd APP_CMD_INIT_WINDOW: onWindowInit() returned, isInited=%d", (int)g_Application->isInited()); break; case APP_CMD_TERM_WINDOW: aout << "APP_CMD_TERM_WINDOW" << std::endl; - DebugLog::log("handle_cmd APP_CMD_TERM_WINDOW: (no handler yet, swapChain/surface still point to dead ANativeWindow)"); + DebugLog::log("handle_cmd APP_CMD_TERM_WINDOW: calling onWindowLost()"); + if (g_Application != nullptr) { + g_Application->onWindowLost(); + } + DebugLog::log("handle_cmd APP_CMD_TERM_WINDOW: onWindowLost() returned"); break; default: break; @@ -116,6 +119,11 @@ void android_main(struct android_app *pApp) { } } } + // isInited() checks _applicationInited && _faceAppInited && _sceondInited, + // so while the window is gone (between TERM_WINDOW and the next + // INIT_WINDOW) this is false and we skip drawFrame entirely — no + // exceptions, no log spam. The outer sleep at the bottom already + // caps the loop frequency. if(g_Application->isInited()) { auto frameTime = (start_time - _lastDrawFrameTime); @@ -123,7 +131,6 @@ void android_main(struct android_app *pApp) { static uint64_t s_frameIdx = 0; static uint64_t s_excCount = 0; - static uint64_t s_lastLoggedExc = 0; ++s_frameIdx; if (s_frameIdx % 600 == 0) { DebugLog::log("heartbeat: frame=%llu exceptions_so_far=%llu", @@ -135,22 +142,17 @@ void android_main(struct android_app *pApp) { g_Application->drawFrame(frameTime); } catch (const std::exception& e) { ++s_excCount; - // Log first 10 exceptions verbosely, then at most one per 120 swallowed. - if (s_excCount <= 10 || (s_excCount - s_lastLoggedExc) >= 120) { - DebugLog::log("!!! drawFrame std::exception (frame=%llu count=%llu): %s", - (unsigned long long)s_frameIdx, - (unsigned long long)s_excCount, - e.what()); - s_lastLoggedExc = s_excCount; - } + DebugLog::log_throttled("main.drawFrame.stdexc", + "!!! drawFrame std::exception (frame=%llu count=%llu): %s", + (unsigned long long)s_frameIdx, + (unsigned long long)s_excCount, + e.what()); } catch (...) { ++s_excCount; - if (s_excCount <= 10 || (s_excCount - s_lastLoggedExc) >= 120) { - DebugLog::log("!!! drawFrame unknown exception (frame=%llu count=%llu)", - (unsigned long long)s_frameIdx, - (unsigned long long)s_excCount); - s_lastLoggedExc = s_excCount; - } + DebugLog::log_throttled("main.drawFrame.unknown", + "!!! drawFrame unknown exception (frame=%llu count=%llu)", + (unsigned long long)s_frameIdx, + (unsigned long long)s_excCount); } } auto end_time = chrono::duration_cast(chrono::system_clock::now().time_since_epoch()).count(); @@ -163,9 +165,11 @@ void android_main(struct android_app *pApp) { this_thread::sleep_for(chrono::milliseconds((35-function_time))); } } while (!pApp->destroyRequested); + DebugLog::log("android_main: destroyRequested, running cleanup"); //application.cleanup(); g_Application->cleanupSecondInit(); g_Application->clearnSecondFaceApp(); + DebugLog::log("android_main: exit"); } } @@ -228,9 +232,9 @@ Java_com_hmwl_face_1sdk_FaceActivity_passDataToNative(JNIEnv *env, jobject thiz, extern "C" JNIEXPORT void JNICALL Java_com_hmwl_face_1sdk_FaceActivity_SetCppInitArg(JNIEnv *env, jobject thiz, jstring json) { - // TODO: implement SetCppInitArg() const char *nativeString = env->GetStringUTFChars(json, nullptr); jsize len = env->GetStringUTFLength(json); + DebugLog::log("JNI SetCppInitArg tid=%d len=%d", dbg_tid(), (int)len); if(len > ArgLen) { aout << "ArgLen to long:" << len << std::endl; @@ -242,6 +246,7 @@ Java_com_hmwl_face_1sdk_FaceActivity_SetCppInitArg(JNIEnv *env, jobject thiz, js extern "C" JNIEXPORT void JNICALL Java_com_hmwl_face_1sdk_FaceActivity_StopRunning(JNIEnv *env, jobject thiz) { + DebugLog::log("JNI StopRunning tid=%d", dbg_tid()); g_Application->Stop(); } @@ -377,6 +382,7 @@ extern "C" JNIEXPORT jstring JNICALL Java_com_hmwl_face_1sdk_FaceActivity_PreReadAction(JNIEnv *env, jobject thiz, jstring motion, jobject callback) { + DebugLog::log("JNI PreReadAction tid=%d", dbg_tid()); // 清理旧的全局引用 if (g_callback != nullptr) { env->DeleteGlobalRef(g_callback); @@ -425,9 +431,11 @@ extern "C" JNIEXPORT void JNICALL Java_com_hmwl_face_1sdk_FaceActivity_ChangeMotionCpp(JNIEnv *env, jobject thiz, jstring json, jobject callback, jboolean loop) { - // TODO: implement ChangeMotionCpp() const char *nativeString = env->GetStringUTFChars(json, nullptr); jsize len = env->GetStringUTFLength(json); + DebugLog::log_throttled("JNI.ChangeMotionCpp", + "JNI ChangeMotionCpp tid=%d len=%d loop=%d", + dbg_tid(), (int)len, (int)loop); if(len > ArgLen) { aout << "ArgLen to long:" << len << std::endl; @@ -450,11 +458,12 @@ Java_com_hmwl_face_1sdk_FaceActivity_ChangeMotionCpp(JNIEnv *env, jobject thiz, extern "C" JNIEXPORT void JNICALL Java_com_hmwl_face_1sdk_FaceActivity_StopMotionNative(JNIEnv *env, jobject thiz) { + DebugLog::log("JNI StopMotionNative tid=%d", dbg_tid()); g_Application->StopMotion(); } extern "C" JNIEXPORT void JNICALL Java_com_hmwl_face_1sdk_FaceActivity_ResumeMotionNative(JNIEnv *env, jobject thiz) { - // TODO: implement ResumeMotionNative() + DebugLog::log("JNI ResumeMotionNative tid=%d", dbg_tid()); g_Application->ResumeMotion(); } \ No newline at end of file diff --git a/vulkan/Application.cpp b/vulkan/Application.cpp index f9d6170..61f4bc9 100644 --- a/vulkan/Application.cpp +++ b/vulkan/Application.cpp @@ -148,6 +148,105 @@ void Application::cleanupSecondInit() _sceondInited = false; } +void Application::cleanupForWindowLost() +{ + if (!_applicationInited || !_sceondInited) { + FACE_DBG_LOG("cleanupForWindowLost: skip (_applicationInited=%d _sceondInited=%d)", + (int)_applicationInited, (int)_sceondInited); + return; + } + FACE_DBG_LOG("cleanupForWindowLost: begin (imageCount=%zu MAX_FRAMES_IN_FLIGHT=%d)", + swapChainImages.size(), MAX_FRAMES_IN_FLIGHT); + + // Block until GPU is no longer using any of the resources we are about + // to destroy. Anything weaker than this risks hitting VK_ERROR_DEVICE_LOST + // on drivers that don't tolerate destroying in-flight resources. + vkDeviceWaitIdle(device); + + for (auto framebuffer : swapChainFramebuffers) { + if (framebuffer != VK_NULL_HANDLE) { + vkDestroyFramebuffer(device, framebuffer, nullptr); + } + } + swapChainFramebuffers.clear(); + + for (auto imageView : swapChainImageViews) { + if (imageView != VK_NULL_HANDLE) { + vkDestroyImageView(device, imageView, nullptr); + } + } + swapChainImageViews.clear(); + + // Free the command buffers allocated from commandPool. The pool itself is + // kept alive so textures/staging uploads that run concurrently off the + // render thread (via commandPool_ex) aren't disrupted. + if (!commandBuffers.empty()) { + vkFreeCommandBuffers(device, commandPool, + (uint32_t)commandBuffers.size(), commandBuffers.data()); + commandBuffers.clear(); + } + + for (size_t i = 0; i < imageAvailableSemaphores.size(); ++i) { + if (imageAvailableSemaphores[i] != VK_NULL_HANDLE) { + vkDestroySemaphore(device, imageAvailableSemaphores[i], nullptr); + } + } + imageAvailableSemaphores.clear(); + for (size_t i = 0; i < renderFinishedSemaphores.size(); ++i) { + if (renderFinishedSemaphores[i] != VK_NULL_HANDLE) { + vkDestroySemaphore(device, renderFinishedSemaphores[i], nullptr); + } + } + renderFinishedSemaphores.clear(); + for (size_t i = 0; i < inFlightFences.size(); ++i) { + if (inFlightFences[i] != VK_NULL_HANDLE) { + vkDestroyFence(device, inFlightFences[i], nullptr); + } + } + inFlightFences.clear(); + imagesInFlight.clear(); + + if (swapChain != VK_NULL_HANDLE) { + vkDestroySwapchainKHR(device, swapChain, nullptr); + swapChain = VK_NULL_HANDLE; + } + swapChainImages.clear(); + + if (surface != VK_NULL_HANDLE) { + vkDestroySurfaceKHR(instance, surface, nullptr); + surface = VK_NULL_HANDLE; + } + + currentFrame = 0; + _sceondInited = false; + FACE_DBG_LOG("cleanupForWindowLost: done"); +} + +void Application::reinitForNewWindow() +{ + if (!_applicationInited) { + FACE_DBG_LOG("reinitForNewWindow: skip, _applicationInited=0 (must go through initVulkan first)"); + return; + } + if (_sceondInited) { + FACE_DBG_LOG("reinitForNewWindow: skip, already _sceondInited=1"); + return; + } + FACE_DBG_LOG("reinitForNewWindow: begin"); + + createSurface(); + createSwapChain(); + createImageViews(); + createFramebuffers(); + createCommandBuffer(); + createSyncObjects(); + + _sceondInited = true; + FACE_DBG_LOG("reinitForNewWindow: done (imageCount=%zu extent=%ux%u MAX_FRAMES_IN_FLIGHT=%d)", + swapChainImages.size(), swapChainExtent.width, swapChainExtent.height, + MAX_FRAMES_IN_FLIGHT); +} + void Application::createImageViews() { @@ -590,18 +689,24 @@ void Application::drawFrame(long long frameTime) // 1. 等待前一帧完成 VkResult waitRes = vkWaitForFences(device, 1, &inFlightFences[currentFrame], VK_TRUE, UINT64_MAX); if (waitRes != VK_SUCCESS) { - FACE_DBG_LOG("drawFrame[%llu] vkWaitForFences -> %d (%s) currentFrame=%u", +#ifndef _WIN32 + DebugLog::log_throttled("drawFrame.waitFences", + "drawFrame[%llu] vkWaitForFences -> %d (%s) currentFrame=%u", (unsigned long long)s_drawFrameCount, (int)waitRes, VkResultStr(waitRes), currentFrame); +#endif } // 2. 获取交换链图像 uint32_t imageIndex; VkResult result = vkAcquireNextImageKHR(device, swapChain, UINT64_MAX, imageAvailableSemaphores[currentFrame], VK_NULL_HANDLE, &imageIndex); if (result != VK_SUCCESS) { - FACE_DBG_LOG("drawFrame[%llu] vkAcquireNextImageKHR -> %d (%s) currentFrame=%u", +#ifndef _WIN32 + DebugLog::log_throttled("drawFrame.acquire", + "drawFrame[%llu] vkAcquireNextImageKHR -> %d (%s) currentFrame=%u", (unsigned long long)s_drawFrameCount, (int)result, VkResultStr(result), currentFrame); +#endif throw std::runtime_error("failed to acquire swap chain image!"); } @@ -634,10 +739,13 @@ void Application::drawFrame(long long frameTime) VkResult submitRes = vkQueueSubmit(graphicsQueue, 1, &submitInfo, inFlightFences[currentFrame]); if (submitRes != VK_SUCCESS) { - FACE_DBG_LOG("drawFrame[%llu] vkQueueSubmit -> %d (%s) currentFrame=%u imageIndex=%u", +#ifndef _WIN32 + DebugLog::log_throttled("drawFrame.submit", + "drawFrame[%llu] vkQueueSubmit -> %d (%s) currentFrame=%u imageIndex=%u", (unsigned long long)s_drawFrameCount, (int)submitRes, VkResultStr(submitRes), currentFrame, imageIndex); +#endif throw std::runtime_error("failed to submit draw command buffer!"); } // 7. 呈现图像 @@ -652,10 +760,13 @@ void Application::drawFrame(long long frameTime) result = vkQueuePresentKHR(presentQueue, &presentInfo); if (result != VK_SUCCESS) { - FACE_DBG_LOG("drawFrame[%llu] vkQueuePresentKHR -> %d (%s) currentFrame=%u imageIndex=%u", +#ifndef _WIN32 + DebugLog::log_throttled("drawFrame.present", + "drawFrame[%llu] vkQueuePresentKHR -> %d (%s) currentFrame=%u imageIndex=%u", (unsigned long long)s_drawFrameCount, (int)result, VkResultStr(result), currentFrame, imageIndex); +#endif throw std::runtime_error("failed to present swap chain image!"); } diff --git a/vulkan/Application.h b/vulkan/Application.h index 7ea5d2e..ad7d62e 100644 --- a/vulkan/Application.h +++ b/vulkan/Application.h @@ -81,6 +81,17 @@ public: bool _applicationInited = false; void cleanupSecondInit(); + // Tear down only the window-dependent Vulkan objects so we can survive an + // Android APP_CMD_TERM_WINDOW (screen off / background / rotate). + // Keeps renderPass / pipelines / VMA / textures / FaceApp resources intact, + // so pipelines created by FaceApp remain valid for the new swapchain. + // Caller MUST hold any app-level mutexes that serialize JNI -> Vulkan access. + void cleanupForWindowLost(); + + // Rebuild the window-dependent Vulkan objects torn down above. + // Safe to call only after cleanupForWindowLost(). + void reinitForNewWindow(); + protected: void loadTexture(std::string path, Texture& tex, bool srgb, VkCommandPool pool); void loadTexture(std::vector& image_data, size_t image_size, int w, int h, Texture& tex, bool srgb, VkCommandPool pool, std::string path); diff --git a/vulkan/FaceApp.cpp b/vulkan/FaceApp.cpp index 56e45eb..459d384 100644 --- a/vulkan/FaceApp.cpp +++ b/vulkan/FaceApp.cpp @@ -32,11 +32,14 @@ FaceApp::~FaceApp() void FaceApp::Stop() { + FACE_DBG_LOG("FaceApp::Stop called (_running=%d worker_joinable=%d)", + (int)_running, (int)worker_.joinable()); _running = false; if(worker_.joinable()) { worker_.join(); } + FACE_DBG_LOG("FaceApp::Stop done"); } void ReceiveFacePoint(float* pos, int pointCount, int width, int height) @@ -858,14 +861,70 @@ void FaceApp::initVulkan() void FaceApp::clearnSecondFaceApp() { + FACE_DBG_LOG("FaceApp::clearnSecondFaceApp: _secondfaceAppInited %d -> 0", + (int)_secondfaceAppInited); _secondfaceAppInited = false; } void FaceApp::Start() { + FACE_DBG_LOG("FaceApp::Start: _running %d -> 1", (int)_running); _running = true; } +void FaceApp::onWindowLost() +{ + FACE_DBG_LOG("FaceApp::onWindowLost enter _applicationInited=%d _faceAppInited=%d _sceondInited=%d _secondfaceAppInited=%d _running=%d", + (int)_applicationInited, (int)_faceAppInited, (int)_sceondInited, + (int)_secondfaceAppInited, (int)_running); + + // Stop the render loop from touching Vulkan while we tear down. + _running = false; + + // Serialize against JNI callbacks that may concurrently submit GPU work + // via commandPool / commandPool_ex (processImageNative -> update texture, + // passDataToNative -> update vertex buffer, changeMotionList). + std::unique_lock lk_point(mtx_point); + std::unique_lock lk_motion(changeMotionMtx); + std::unique_lock lk_tex(createTextureMtx); + + Application::cleanupForWindowLost(); + _secondfaceAppInited = false; + + FACE_DBG_LOG("FaceApp::onWindowLost done"); +} + +void FaceApp::onWindowInit() +{ + FACE_DBG_LOG("FaceApp::onWindowInit enter _applicationInited=%d _faceAppInited=%d _sceondInited=%d _secondfaceAppInited=%d", + (int)_applicationInited, (int)_faceAppInited, (int)_sceondInited, + (int)_secondfaceAppInited); + + if (!_applicationInited) { + // First-time path: go through the full initVulkan pipeline. + initVulkan(); + } else { + // Recovery path after an earlier onWindowLost. Rebuild only the + // window-dependent Vulkan objects; keep renderPass / pipelines / + // FaceApp GPU resources intact. + std::unique_lock lk_point(mtx_point); + std::unique_lock lk_motion(changeMotionMtx); + std::unique_lock lk_tex(createTextureMtx); + + Application::reinitForNewWindow(); + + if (!_secondfaceAppInited) { + _secondfaceAppInited = true; + _playMotion = true; + _running = true; + } + } + + FACE_DBG_LOG("FaceApp::onWindowInit done _applicationInited=%d _faceAppInited=%d _sceondInited=%d _secondfaceAppInited=%d _running=%d", + (int)_applicationInited, (int)_faceAppInited, (int)_sceondInited, + (int)_secondfaceAppInited, (int)_running); +} + void FaceApp::update_uniform_buffers() { uint32_t width = 480; @@ -1340,6 +1399,7 @@ void FaceApp::cleanupResources(VkDevice device, VmaAllocator allocator) { void FaceApp::cleanup() { + FACE_DBG_LOG("FaceApp::cleanup enter"); vkDeviceWaitIdle(device); if (uniform_buffer_mapped != nullptr) @@ -1375,7 +1435,7 @@ void FaceApp::cleanup() // allocator = VK_NULL_HANDLE; //} - + FACE_DBG_LOG("FaceApp::cleanup done"); } @@ -1481,6 +1541,8 @@ void FaceApp::drawFrame(long long frameTime) string FaceApp::preLoadMotionList(string motion_list_str, Callback callback) { + FACE_DBG_LOG("FaceApp::preLoadMotionList called str_len=%zu _isLoadMotion=%d", + motion_list_str.size(), (int)_isLoadMotion); if (_isLoadMotion) { return "failue load not finished"; @@ -1496,11 +1558,13 @@ string FaceApp::preLoadMotionList(string motion_list_str, Callback callback) worker_.join(); } worker_ = std::thread(&FaceApp::loadMotionThread, this); + FACE_DBG_LOG("FaceApp::preLoadMotionList worker_ started, todo_count=%zu", _curLoadMotionList.size()); return "ok"; } void FaceApp::loadMotionThread() { + FACE_DBG_LOG("FaceApp::loadMotionThread enter, todo_count=%zu", _curLoadMotionList.size()); while (!isInited()) { std::this_thread::sleep_for(std::chrono::milliseconds(50)); @@ -1561,6 +1625,7 @@ void FaceApp::loadMotionThread() // } update_descriptor_set(m_texs_left, m_descriptor_sets_left); _isLoadMotion = false; + FACE_DBG_LOG("FaceApp::loadMotionThread done, loaded_total=%zu", motion_list_map.size()); _callback_loadfinish(); } @@ -1572,6 +1637,9 @@ Motion FaceApp::getMotionByName(string name) void FaceApp::changeMotionList(vector motions, AnimationFinishedCallback callback, bool loop) { + DebugLog::log_throttled("FaceApp.changeMotionList", + "FaceApp::changeMotionList called count=%zu loop=%d _isLoadMotion=%d", + motions.size(), (int)loop, (int)_isLoadMotion); if (_isLoadMotion) { return; @@ -1623,10 +1691,12 @@ void FaceApp::changeMotionList(vector motions, AnimationFinishedCallback } void FaceApp::StopMotion() { + FACE_DBG_LOG("FaceApp::StopMotion: _playMotion %d -> 0", (int)_playMotion); _playMotion = false; } void FaceApp::ResumeMotion() { + FACE_DBG_LOG("FaceApp::ResumeMotion: _playMotion %d -> 1", (int)_playMotion); _playMotion = true; } diff --git a/vulkan/FaceApp.h b/vulkan/FaceApp.h index f6df3c7..244d903 100644 --- a/vulkan/FaceApp.h +++ b/vulkan/FaceApp.h @@ -182,6 +182,17 @@ public: void clearnSecondFaceApp(); void Start(); void Stop(); + + // Called from main thread in response to APP_CMD_TERM_WINDOW. + // Serializes against JNI callbacks (processImageNative / passDataToNative / + // changeMotionList) by taking all three FaceApp mutexes + createTextureMtx, + // then tears down window-dependent Vulkan objects via Application. + void onWindowLost(); + + // Called from main thread in response to APP_CMD_INIT_WINDOW. + // Does the full first-time initVulkan() on the very first call, and a + // lightweight swapchain/surface rebuild on subsequent calls. + void onWindowInit(); void loadMotionThread(); std::thread worker_; bool _isLoadMotion = false;