xsl/face_sdk
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fix bug and add log

Browse Source
This commit is contained in:
xsl
2026-04-23 22:18:22 +08:00
parent fb434f09b8
commit 27b7075818
7 changed files with 327 additions and 40 deletions
Download Patch File Download Diff File Expand all files Collapse all files
app/src/main/cpp/DebugLog.cpp
+79 -12
View File
@@ -8,7 +8,10 @@
#include <cstdarg>
#include <cstdio>
#include <ctime>
#include <cstring>
#include <mutex>
#include <string>
#include <unordered_map>
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<std::string, ThrottleSlot> g_throttle;
constexpr int64_t kThrottleWindowMs = 2000; // 2 seconds
pid_t currentTid() {
return static_cast<pid_t>(syscall(SYS_gettid));
}
int64_t nowMs() {
timespec ts{};
clock_gettime(CLOCK_MONOTONIC, &ts);
return static_cast<int64_t>(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<std::mutex> 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<std::mutex> 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() {
app/src/main/cpp/DebugLog.h
+8
View File
@@ -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();
app/src/main/cpp/main.cpp
+32 -23
View File
@@ -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::milliseconds>(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();
}