Skip to content

Commit c6ad81c

Browse files
wolfgitprwolfgitpr
committed
fix(g2p): add thread safety mutex to Manager::initialize() + diagnostic logging
1 parent a6e583b commit c6ad81c

4 files changed

Lines changed: 104 additions & 4 deletions

File tree

‎lib/G2P/Core/Manager.cpp‎

Lines changed: 61 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33
#include <algorithm>
44
#include <mutex>
55
#include <shared_mutex>
6+
#include <thread>
67

78
#include <stdcorelib/path.h>
89
#include <stdcorelib/pimpl.h>
@@ -88,11 +89,21 @@ namespace srt::g2p {
8889
srt::core::Expected<void> Manager::initialize() {
8990
auto &impl = *static_cast<PackageManager::Impl *>(_impl.get());
9091

92+
// Thread safety: prevent concurrent entry. Without this lock, two
93+
// threads calling initializeModels() simultaneously (e.g.
94+
// InitInferEngineTask + GetPronunciationTask) could both pass the
95+
// m_initialized check and enter the init path together, causing
96+
// state corruption or hangs in ONNX session creation.
97+
std::lock_guard<std::mutex> initLock(impl.m_init_mtx);
98+
9199
if (impl.m_initialized) {
92100
return Error(ErrorCode::G2pAlreadyInitialized,
93101
"Manager::initialize() has already been called");
94102
}
95103

104+
g2pLog.srtInfo("Manager::initialize: START (thread=%1)",
105+
std::hash<std::thread::id>{}(std::this_thread::get_id()));
106+
96107
// Phase 1: Default context (official G2P).
97108
// Allow empty default context: when no official G2P packages are
98109
// registered (voicebank-only deployment), skip Phase 1 entirely and
@@ -101,8 +112,11 @@ namespace srt::g2p {
101112
// honors ds-session.md §210: "某 G2P module 初始化失败：仅关联
102113
// singer-language Disabled，其他语言/声库仍可发布".
103114
{
115+
g2pLog.srtInfo("Manager::initialize: Phase 1 (default context) START");
104116
srt::core::ContextKey defaultCtx("");
105117
const auto moduleInfos = this->getModuleMetadatas(defaultCtx);
118+
g2pLog.srtInfo("Manager::initialize: Phase 1 moduleMetadatas count=%1",
119+
moduleInfos.size());
106120
if (moduleInfos.empty()) {
107121
// Diagnostic: log registered paths and their filesystem status
108122
// to identify why the default context has no modules. Remove
@@ -158,26 +172,40 @@ namespace srt::g2p {
158172
}
159173

160174
auto packageOrder = depGraph.getPackageInitializationOrder();
175+
g2pLog.srtInfo("Manager::initialize: Phase 1 packageOrder size=%1",
176+
packageOrder.size());
161177
int failedPkgCount = 0;
162178
std::vector<std::string> pkgErrors;
163179
for (const auto &packageInfo : packageOrder) {
180+
g2pLog.srtInfo("Manager::initialize: Phase 1 opening package=%1 path=%2",
181+
packageInfo.packageId,
182+
stdc::path::to_utf8(packageInfo.packagePath));
164183
auto exp = this->open(packageInfo.packagePath);
165184
if (!exp) {
185+
g2pLog.srtWarning("Manager::initialize: Phase 1 open FAILED package=%1: %2",
186+
packageInfo.packageId, exp.error().message());
166187
pkgErrors.push_back(packageInfo.packageId + ": " + exp.error().message());
167188
failedPkgCount++;
168189
continue;
169190
}
170191

171192
Package pkg = exp.take();
172193
if (!pkg.isLoaded()) {
194+
g2pLog.srtWarning("Manager::initialize: Phase 1 pkg not loaded package=%1: %2",
195+
packageInfo.packageId, pkg.error().message());
173196
pkgErrors.push_back(packageInfo.packageId + ": " + pkg.error().message());
174197
failedPkgCount++;
175198
continue;
176199
}
177200

201+
g2pLog.srtInfo("Manager::initialize: Phase 1 package=%1 loaded, creating %2 tasks",
202+
packageInfo.packageId, packageInfo.initializationOrder.size());
178203
for (const auto &moduleInfo : packageInfo.initializationOrder) {
204+
g2pLog.srtInfo("Manager::initialize: Phase 1 creating task module=%1 type=%2 iid=%3",
205+
moduleInfo.moduleId, moduleInfo.type, moduleInfo.iid);
179206
auto taskExp = createModuleTask(moduleInfo, pkg);
180207
if (taskExp) {
208+
g2pLog.srtInfo("Manager::initialize: Phase 1 task created OK module=%1", moduleInfo.moduleId);
181209
const auto fqid = ContextUtils::formatFqid(defaultCtx, moduleInfo.moduleId);
182210
if (auto *cate = this->category(moduleInfo.type)) {
183211
cate->addObject(fqid, taskExp.value());
@@ -199,23 +227,31 @@ namespace srt::g2p {
199227
}
200228

201229
impl.m_contextStates[defaultCtx] = ContextState::Ready;
230+
g2pLog.srtInfo("Manager::initialize: Phase 1 default context Ready");
202231
}
203232
}
204233
}
234+
g2pLog.srtInfo("Manager::initialize: Phase 1 END");
205235

206236
// Phase 2: Non-default contexts
237+
g2pLog.srtInfo("Manager::initialize: Phase 2 START, contextPaths=%1",
238+
impl.m_contextPackagePaths.size());
207239
for (const auto &[ctxKey, _] : impl.m_contextPackagePaths) {
208240
if (ctxKey.isDefault())
209241
continue;
210242

243+
g2pLog.srtInfo("Manager::initialize: Phase 2 context=%1 v=%2 START",
244+
ctxKey.context, ctxKey.version.toString());
211245
const auto moduleInfos = this->getModuleMetadatas(ctxKey);
212246
if (moduleInfos.empty()) {
247+
g2pLog.srtWarning("Manager::initialize: Phase 2 context=%1 no modules", ctxKey.context);
213248
impl.m_contextStates[ctxKey] = ContextState::Failed;
214249
continue;
215250
}
216251

217252
auto compatibleModules = filterCompatibleModules(moduleInfos);
218253
if (compatibleModules.empty()) {
254+
g2pLog.srtWarning("Manager::initialize: Phase 2 context=%1 no compatible modules", ctxKey.context);
219255
impl.m_contextStates[ctxKey] = ContextState::Failed;
220256
continue;
221257
}
@@ -226,26 +262,41 @@ namespace srt::g2p {
226262
depGraph.addModule(info);
227263

228264
if (!depGraph.buildGraph()) {
265+
g2pLog.srtWarning("Manager::initialize: Phase 2 context=%1 buildGraph failed", ctxKey.context);
229266
impl.m_contextStates[ctxKey] = ContextState::Failed;
230267
continue;
231268
}
232269

233270
if (const auto cycles = depGraph.findCycles(); !cycles.empty()) {
271+
g2pLog.srtWarning("Manager::initialize: Phase 2 context=%1 cycles detected", ctxKey.context);
234272
impl.m_contextStates[ctxKey] = ContextState::Failed;
235273
continue;
236274
}
237275

238276
auto packageOrder = depGraph.getPackageInitializationOrder();
277+
g2pLog.srtInfo("Manager::initialize: Phase 2 context=%1 packageOrder size=%2",
278+
ctxKey.context, packageOrder.size());
239279
bool allFailed = true;
240280
for (const auto &packageInfo : packageOrder) {
281+
g2pLog.srtInfo("Manager::initialize: Phase 2 opening package=%1 path=%2",
282+
packageInfo.packageId,
283+
stdc::path::to_utf8(packageInfo.packagePath));
241284
auto exp = this->open(packageInfo.packagePath);
242-
if (!exp)
285+
if (!exp) {
286+
g2pLog.srtWarning("Manager::initialize: Phase 2 open FAILED package=%1: %2",
287+
packageInfo.packageId, exp.error().message());
243288
continue;
289+
}
244290

245291
Package pkg = exp.take();
246-
if (!pkg.isLoaded())
292+
if (!pkg.isLoaded()) {
293+
g2pLog.srtWarning("Manager::initialize: Phase 2 pkg not loaded package=%1: %2",
294+
packageInfo.packageId, pkg.error().message());
247295
continue;
296+
}
248297

298+
g2pLog.srtInfo("Manager::initialize: Phase 2 package=%1 loaded, creating %2 tasks",
299+
packageInfo.packageId, packageInfo.initializationOrder.size());
249300
allFailed = false;
250301
for (const auto &moduleInfo : packageInfo.initializationOrder) {
251302
auto taskExp = createModuleTask(moduleInfo, pkg);
@@ -266,21 +317,29 @@ namespace srt::g2p {
266317
impl.m_contextStates[ctxKey] = ContextState::Failed;
267318
} else {
268319
impl.m_contextStates[ctxKey] = ContextState::Ready;
320+
g2pLog.srtInfo("Manager::initialize: Phase 2 context=%1 Ready", ctxKey.context);
269321
}
270322
}
323+
g2pLog.srtInfo("Manager::initialize: Phase 2 END");
271324

272325
// Phase 3: Load tasks for categories
326+
g2pLog.srtInfo("Manager::initialize: Phase 3 (loadTasksForCategory g2p) START");
273327
if (auto result = loadTasksForCategory(kG2pCategory); !result) {
328+
g2pLog.srtWarning("Manager::initialize: Phase 3 g2p FAILED: %1", result.error().message());
274329
return std::move(result.takeError()
275330
.withTrace(std::source_location::current(), "Manager::initialize"));
276331
}
332+
g2pLog.srtInfo("Manager::initialize: Phase 3 (loadTasksForCategory g2p) END");
277333

334+
g2pLog.srtInfo("Manager::initialize: Phase 3 (loadTasksForCategory dict) START");
278335
if (auto result = loadTasksForCategory(kDictCategory); !result) {
279336
// dict is optional - log warning but continue initialization
280337
g2pLog.srtWarning("Dict task init failed - %1", result.error().message());
281338
}
339+
g2pLog.srtInfo("Manager::initialize: Phase 3 (loadTasksForCategory dict) END");
282340

283341
impl.m_initialized = true;
342+
g2pLog.srtInfo("Manager::initialize: COMPLETE (m_initialized=true)");
284343
return {};
285344
}
286345

‎lib/G2P/Core/PackageManager.cpp‎

Lines changed: 20 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -959,8 +959,15 @@ namespace srt::g2p {
959959

960960
srt::core::Expected<srt::core::NO<Task>>
961961
PackageManager::createModuleTask(const srt::dependency::ModuleMetadata &moduleInfo, const Package &pkg) const {
962+
// Diagnostic logging: trace each step of task creation to identify hangs.
963+
// Remove after root cause is identified.
964+
static srt::core::LogCategory pkgMgrLog("PackageManager");
965+
pkgMgrLog.srtInfo("createModuleTask: START module=%1 type=%2 iid=%3",
966+
moduleInfo.moduleId, moduleInfo.type, moduleInfo.iid);
967+
962968
auto *moduleSpec = pkg.moduleSpec(moduleInfo.type, moduleInfo.moduleId);
963969
if (!moduleSpec) {
970+
pkgMgrLog.srtWarning("createModuleTask: moduleSpec not found module=%1", moduleInfo.moduleId);
964971
return Error::g2pError(ErrorCode::G2pPackageNotFound,
965972
stdc::formatN("Module not found: package=%1, moduleId=%2, type=%3",
966973
moduleInfo.packageId, moduleInfo.moduleId, moduleInfo.type),
@@ -969,22 +976,33 @@ namespace srt::g2p {
969976

970977
moduleSpec->_impl->m_contextKey = srt::core::ContextKey(moduleInfo.context, moduleInfo.contextVersion);
971978

979+
pkgMgrLog.srtInfo("createModuleTask: looking up task plugin iid=%1", moduleInfo.iid);
972980
auto *taskPlugin = this->plugin<TaskPlugin>(moduleInfo.iid.c_str());
973981
if (!taskPlugin) {
982+
pkgMgrLog.srtWarning("createModuleTask: task plugin not found iid=%1", moduleInfo.iid);
974983
return Error::g2pError(ErrorCode::G2pRuntimeError,
975984
stdc::formatN("Task plugin not found for iid: %1", moduleInfo.iid), {},
976985
moduleInfo.packageId);
977986
}
978987

988+
pkgMgrLog.srtInfo("createModuleTask: calling createTask module=%1", moduleInfo.moduleId);
979989
auto taskExp = taskPlugin->createTask(moduleSpec);
980-
if (!taskExp)
990+
if (!taskExp) {
991+
pkgMgrLog.srtWarning("createModuleTask: createTask failed module=%1: %2",
992+
moduleInfo.moduleId, taskExp.error().message());
981993
return taskExp.error();
994+
}
982995

983996
auto task = taskExp.take();
997+
pkgMgrLog.srtInfo("createModuleTask: calling task->initialize module=%1", moduleInfo.moduleId);
984998
auto initExp = task->initialize();
985-
if (!initExp)
999+
if (!initExp) {
1000+
pkgMgrLog.srtWarning("createModuleTask: task->initialize failed module=%1: %2",
1001+
moduleInfo.moduleId, initExp.error().message());
9861002
return initExp.error();
1003+
}
9871004

1005+
pkgMgrLog.srtInfo("createModuleTask: SUCCESS module=%1", moduleInfo.moduleId);
9881006
return task;
9891007
}
9901008

‎lib/G2P/Core/PackageManager_p.h‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -92,6 +92,13 @@ namespace srt::g2p {
9292

9393
bool m_initialized = false;
9494

95+
// Protects Manager::initialize() against concurrent entry. Without this,
96+
// two threads calling initializeModels() simultaneously (e.g.
97+
// InitInferEngineTask + GetPronunciationTask) could both pass the
98+
// m_initialized check and enter the init path together, causing state
99+
// corruption or hangs in ONNX session creation.
100+
mutable std::mutex m_init_mtx;
101+
95102
static constexpr int kCurrentLevel = 2;
96103
static constexpr int kMaximumLevel = 2;
97104
static constexpr int kMinimumLevel = 1;

‎lib/G2P/LanguageServiceLang.cpp‎

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -656,7 +656,10 @@ namespace srt::g2p {
656656
}
657657

658658
srt::core::Expected<void> LanguageService::initializeModels() {
659+
langSvcLog.srtInfo("initializeModels: START metadataReady=%1 modelsReady=%2",
660+
_impl->metadataReady, _impl->modelsReady);
659661
if (!_impl->metadataReady) {
662+
langSvcLog.srtWarning("initializeModels: metadata not ready");
660663
return srt::core::Error(
661664
srt::core::ErrorCode::G2pInitializationError,
662665
"initializeModels() requires initializeMetadata() first");
@@ -665,21 +668,34 @@ namespace srt::g2p {
665668
auto mgr = srt::g2p::Manager::instance();
666669
if (mgr->initialized()) {
667670
// Idempotent: already initialized by another LanguageService instance.
671+
langSvcLog.srtInfo("initializeModels: Manager already initialized, marking modelsReady");
668672
_impl->modelsReady = true;
669673
return {};
670674
}
671675

672676
// Stage 2: Initialize all registered G2P contexts (load plugins, create
673677
// ONNX sessions). Failure terminates G2P conversion but route resolution
674678
// (Stage 1) remains available.
679+
langSvcLog.srtInfo("initializeModels: calling Manager::initialize()");
675680
auto g2pResult = mgr->initialize();
676681
if (!g2pResult) {
682+
// G2pAlreadyInitialized is not a real failure: another thread won
683+
// the init race while we were waiting for the init mutex. The
684+
// Manager is now initialized, so we can proceed.
685+
if (g2pResult.error().code() == srt::core::ErrorCode::G2pAlreadyInitialized) {
686+
langSvcLog.srtInfo("initializeModels: Manager already initialized by another thread, marking modelsReady");
687+
_impl->modelsReady = true;
688+
return {};
689+
}
690+
langSvcLog.srtWarning("initializeModels: Manager::initialize FAILED: %1",
691+
g2pResult.error().message());
677692
return srt::core::Error(
678693
srt::core::ErrorCode::G2pInitializationError,
679694
"G2P Manager initialization failed: " +
680695
g2pResult.error().message());
681696
}
682697

698+
langSvcLog.srtInfo("initializeModels: Manager::initialize succeeded, marking modelsReady");
683699
_impl->modelsReady = true;
684700
return {};
685701
}

0 commit comments

Comments
 (0)