diag: 增加调用栈抓取，定位开图期 1140 次截面回写的成因 #101
No files matched your search
@@ -1275,6 +1275,18 @@ Acad::ErrorStatus AecDbEwPipeBase::BaseCurveDwgOutFields(AcDbCurve* pBaseCurve,A
|
||||
Acad::ErrorStatus AecDbEwPipeBase::RegionAcisoutDwgOutFields(AcDbDwgFiler* pFiler) const
|
||||
{
|
||||
// Phase 0 计数：回写（Region -> SAT 文本）的次数与耗时
|
||||
// 诊断：AEC_WRITEBACK_TRACE=1 时抓一次调用栈，确认开图期是谁在回写实体
|
||||
{
|
||||
static bool s_bTraced = false;
|
||||
if (!s_bTraced)
|
||||
{
|
||||
s_bTraced = true;
|
||||
const char* pszTrace = ::getenv("AEC_WRITEBACK_TRACE");
|
||||
if (pszTrace != NULL && pszTrace[0] != '0')
|
||||
SectionPerf::TraceCallStack("EwPipe::RegionAcisout (first call)", 2);
|
||||
}
|
||||
}
|
||||
|
||||
SectionPerf::Scope perfScope("EwPipe::RegionAcisout");
|
||||
SectionPerf::NoteWriteBack("EwPipe::RegionAcisout");
|
||||
|
||||
|
||||
@@ -344,6 +344,52 @@ namespace SectionPerf
|
||||
}
|
||||
}
|
||||
|
||||
void TraceCallStack(const char* pszTag, int nSkip)
|
||||
{
|
||||
typedef USHORT(WINAPI* PFN_CaptureStack)(ULONG, ULONG, PVOID*, PULONG);
|
||||
static PFN_CaptureStack s_pfn = NULL;
|
||||
static bool s_bTried = false;
|
||||
if (!s_bTried)
|
||||
{
|
||||
s_bTried = true;
|
||||
HMODULE hNtdll = ::GetModuleHandleA("ntdll.dll");
|
||||
if (hNtdll != NULL)
|
||||
s_pfn = (PFN_CaptureStack)::GetProcAddress(hNtdll, "RtlCaptureStackBackTrace");
|
||||
}
|
||||
if (s_pfn == NULL)
|
||||
return;
|
||||
|
||||
void* frames[24];
|
||||
::memset(frames, 0, sizeof(frames));
|
||||
const USHORT nGot = s_pfn((ULONG)(nSkip > 0 ? nSkip : 0), 24, frames, NULL);
|
||||
|
||||
std::string out = "\n[stack] ";
|
||||
out += (pszTag != NULL ? pszTag : "?");
|
||||
out += "\n";
|
||||
char szLine[1024];
|
||||
for (USHORT i = 0; i < nGot; ++i)
|
||||
{
|
||||
const DWORD64 nAddr = (DWORD64)frames[i];
|
||||
HMODULE hMod = NULL;
|
||||
if (!::GetModuleHandleExW(GET_MODULE_HANDLE_EX_FLAG_FROM_ADDRESS | GET_MODULE_HANDLE_EX_FLAG_UNCHANGED_REFCOUNT,
|
||||
(LPCWSTR)nAddr, &hMod) || hMod == NULL)
|
||||
continue;
|
||||
|
||||
WCHAR szPath[MAX_PATH];
|
||||
::memset(szPath, 0, sizeof(szPath));
|
||||
::GetModuleFileNameW(hMod, szPath, MAX_PATH);
|
||||
const WCHAR* pszBase = wcsrchr(szPath, L'\\');
|
||||
pszBase = (pszBase != NULL) ? pszBase + 1 : szPath;
|
||||
|
||||
char szMod[MAX_PATH * 2];
|
||||
::memset(szMod, 0, sizeof(szMod));
|
||||
::WideCharToMultiByte(CP_ACP, 0, pszBase, -1, szMod, sizeof(szMod) - 1, NULL, NULL);
|
||||
sprintf_s(szLine, sizeof(szLine), " %-28s +0x%llx\n", szMod, (unsigned long long)(nAddr - (DWORD64)hMod));
|
||||
out += szLine;
|
||||
}
|
||||
AppendReport(out.c_str());
|
||||
}
|
||||
|
||||
void AppendReport(const char* pszText)
|
||||
{
|
||||
if (pszText == NULL)
|
||||
|
||||
@@ -76,9 +76,12 @@ namespace SectionPerf
|
||||
// 打印 + 写文件
|
||||
void Dump();
|
||||
|
||||
// 只追加文本到 %TEMP%ec_section_perf.txt（供其它模块复用同一份报告）
|
||||
// 只追加文本到 %TEMP%\aec_section_perf.txt（供其它模块复用同一份报告）
|
||||
void AppendReport(const char* pszText);
|
||||
|
||||
// 抓一次调用栈写进报告，用于定位"谁在开图期回写实体"这类问题
|
||||
void TraceCallStack(const char* pszTag, int nSkip = 1);
|
||||
|
||||
// 清零
|
||||
void Reset();
|
||||
}
|
||||
|
||||
@@ -277,13 +277,61 @@ clone 成本可以忽略，说明"每次无论命中与否都发 clone"这个保
|
||||
|
||||
#### 仍未解决
|
||||
|
||||
1. `EwPipe::RegionAcisout` 仍是 **1140 次 / 2.38 s**，开图期间把几何又序列化回 SAT，
|
||||
与缓存无关，应单独立项。
|
||||
1. `EwPipe::RegionAcisout` 仍是 **1140 次 / 2.38 s**——已查明原因，见下节。
|
||||
2. `Fitting::GetSection` 在**开图**阶段只有 232 次调用（0.13 s），收益很小；
|
||||
它的价值可能在绘制/平移时，需要另一次针对"打开后操作"的测量才能确认。
|
||||
3. `StringToRegion` 仍有 1570 次未命中（唯一文本 1562），这部分是真实的不同截面，
|
||||
想再提升只能靠业务层的 key，暂不做。
|
||||
|
||||
### 开图期 1140 次回写（RegionAcisout）的成因
|
||||
|
||||
用 `AEC_WRITEBACK_TRACE=1` 抓了一次调用栈（`SectionPerf::TraceCallStack`，输出在报告文件里）：
|
||||
|
||||
```
|
||||
aecrxbase.arx +0x21cb4 AecDbCurveBase::subViewportDraw
|
||||
aecrxbase.arx +0x28905 AecDbEntityCommon::base_ViewportDraw
|
||||
corecommand.arx +0x7ddcef ← 绘制路径里的我们的代码（未解析到符号）
|
||||
corecommand.arx +0x7e09d0
|
||||
corecommand.arx +0x7e1300
|
||||
acdb23.dll +0x97a6b
|
||||
ac1st23.dll +0x19847
|
||||
corecommand.arx +0x58f051 ← AecDbEntityCommon::base_DeepClone
|
||||
acdb23.dll +0x558e3 AcDbObject::dwgOut
|
||||
corecommand.arx +0x58eb33 AecDbEwPipeBase::dwgOutFields
|
||||
corecommand.arx +0x59627b AecDbEwPipeBase::RegionAcisoutDwgOutFields
|
||||
```
|
||||
|
||||
**结论：不是保存，是"绘制期深拷贝"。**
|
||||
|
||||
`AecRxBase/AecDbEntityCommon.cpp:1265`（`base_DeepClone`）用最朴素的方式实现深拷贝：
|
||||
|
||||
```cpp
|
||||
AcDbDeepCloneFiler filer;
|
||||
GetMe()->dwgOut(&filer); // → dwgOutFields → acisOut 写临时 SAT 文件
|
||||
filer.seek(0L, AcDb::kSeekFromStart);
|
||||
pClone->dwgIn(&filer); // → dwgInFields → acisIn 读回来
|
||||
```
|
||||
|
||||
于是**每次绘制期克隆实体，截面都要"写一个 SAT 临时文件、再读回来"**。
|
||||
1140 次 × 2.08 ms ≈ 2.38 s，全部发生在开图的绘制阶段。
|
||||
|
||||
（读的那一半现在已被 kText 缓存吃掉；剩下的是 `acisOut` 写文件这一半。）
|
||||
|
||||
触发点：绘制路径里有 `clone()`（栈帧在 corecommand.arx 内，未解析到符号）。
|
||||
代码里一处明确的可疑点是 `AecDbX3dPartEntity::subGetTransformedCopy`
|
||||
（`AecDbX3dPartEntity.cpp:757` 直接 `clone()`），但**尚未证实它就是本次的调用者**，
|
||||
需要用 PDB 解析上面三个 RVA 才能钉死。
|
||||
|
||||
可选修法（都需要动 `base_DeepClone` 的契约，属于结构性改动，建议单独立项）：
|
||||
|
||||
| 方案 | 做法 | 风险 |
|
||||
| --- | --- | --- |
|
||||
| A | 用 `pFiler->isKindOf(AcDbDeepCloneFiler::desc())` 识别深拷贝，`dwgOutFields` 只写占位符不落盘；克隆完成后由 `base_DeepClone` 用 `m_pRegion->clone()` 在内存里补 | 要给 `AecDbEntityCommon` 加一个"重数据拷贝"的虚钩子，影响面大 |
|
||||
| B | 缓存里同时保存每份 SAT 的原文，`dwgOutFields` 直接写缓存文本，省掉 `acisOut` | 若 `m_pRegion` 在 restore 之后被就地修改过，写出去的是旧几何——必须先审计全库对 `m_pRegion` 的写操作 |
|
||||
| C | 维持现状 | 每次开图多 ~2.4 s（占 98 s 的 2.4%） |
|
||||
|
||||
**A 与 B 都需要先做代码审计**，不适合和本缓存改动混在一起。
|
||||
|
||||
### Phase 2：临时目录治理（可选，止血）
|
||||
|
||||
Phase 1 之后残余落盘只剩"每个唯一截面一次"，收益小；但如果现场仍被杀软拖慢，可做这一步：
|
||||
|
||||
Reference in new issue
Block a user