company-desktop
facf14699b
现象：开图时 X3dPart 的 EnsureCreated 命中率只有 10.1%，1914 次重建里 721 次产出 NULL（38%），单个对象最多被重建 544 次。 根因：EnsureCreated 的命中条件是 !m_bNeedCreate && m_pSolid != NULL， 而 Rebuild() 里对 Hide 构件是"故意不建几何、直接 return true"—— m_pSolid 按设计就是 NULL，于是每次访问都重新走一遍 Rebuild，永远不可能命中。 子项全为空的构件同理。 修复： - 新增 m_bCreated 标记"已经尝试建过"（无论是否产出实体） - EnsureCreated 命中条件改为 !m_bNeedCreate && (m_bCreated || m_pSolid != NULL) - Rebuild 入口置 m_bCreated = true；所有设 m_bNeedCreate = true 的 setter 同时置 m_bCreated = false，保证参数变化后仍会重建 - 重建后仍无实体时打一条日志（限前 5 条，带 m_sName），方便定位是哪些构件 实测（big1.dwg / R230 Debug）： X3dPart 命中率 10.1% -> 41.4% 重建次数 1914 -> 1248（-666） rebuild_null 721 -> 55 单对象最多重建 544 -> <=3 开图墙钟 93 s -> 93 s（无变化） 注意：这 666 次空转没有带来可测的提速，因为 Rebuild 里 Hide 的早退分支在 布尔运算之前，每次只有几微秒。所以这是正确性/整洁度修复，不是性能修复； 但消除了"个别构件被重试几百次"这种病态行为，也暴露了"哪些构件建不出实体"。 顺带新增诊断（Debug + AEC_PERF_COUNTER=1 才生效，Release 无开销）： - SectionPerf::NoteEnsure()：按 tag 统计"延迟建几何"的命中/重建， 并给出对象维度直方图与重建次数最高的对象 - AecDbX3dPart::Rebuild / AcDbX3dSolid::EnsureCreated / AecDbGuardBar::Draw3d 打点 - tools/run_acad_perf.ps1 增加 -CpuTrace：用 xperf 采 CPU 采样并 merge 成 etl， 可直接喂 tools/perf_diagsession.py（VS 的 VSDiagnostics 在这台机器上会卡住， wpr -stop 有 COM 线程模式 bug，故用 xperf） 验证：R230 Debug 编译通过并部署，自动开图取数；截面缓存与回写仍为 0/正常。
530 lines
14 KiB
C++
530 lines
14 KiB
C++
#include "stdafx.h"
|
||
#include "SectionPerfCounter.h"
|
||
#include "SectionRegionCache.h"
|
||
|
||
#include <windows.h>
|
||
#include <stdlib.h>
|
||
#include <string>
|
||
#include <map>
|
||
#include <set>
|
||
|
||
namespace
|
||
{
|
||
// 单个计数器：次数 + 累计耗时（µs）
|
||
struct Entry
|
||
{
|
||
Entry() : nCount(0), nTotalUs(0), nMaxUs(0) {}
|
||
|
||
unsigned long long nCount;
|
||
unsigned long long nTotalUs;
|
||
unsigned long long nMaxUs;
|
||
};
|
||
|
||
// 唯一 hash 表的上限：正常图纸几十到几百个唯一截面，
|
||
// 万一文本各不相同（说明缓存没意义）也不让内存无限涨
|
||
const size_t kMaxUniqueHash = 50000;
|
||
|
||
// 单个属性 key 的统计（按实体类分开看，管道与管件的命中率往往不一样）
|
||
struct KeyStat
|
||
{
|
||
KeyStat() : nTotal(0), nUnique(0), nHits(0), bOverflow(false) {}
|
||
|
||
unsigned long long nTotal;
|
||
size_t nUnique;
|
||
unsigned long long nHits;
|
||
bool bOverflow;
|
||
std::set<unsigned long long> seen;
|
||
};
|
||
|
||
// 每个"延迟建几何"缓存点的统计
|
||
struct EnsureStat
|
||
{
|
||
EnsureStat() : nTotal(0), nHits(0), nRebuilds(0) {}
|
||
|
||
unsigned long long nTotal;
|
||
unsigned long long nHits;
|
||
unsigned long long nRebuilds;
|
||
std::map<const void*, int> builds; // 对象 -> 被建次数
|
||
};
|
||
|
||
struct Stats
|
||
{
|
||
Stats()
|
||
: bInited(false), bEnabled(false)
|
||
, nRegionTexts(0), nUniqueHashes(0), nSimulatedHits(0), bHashTableOverflow(false)
|
||
, nTempFiles(0), nTempFileBytes(0)
|
||
, nWriteBacks(0)
|
||
{
|
||
}
|
||
|
||
bool bInited;
|
||
bool bEnabled;
|
||
|
||
std::map<std::string, Entry> entries; // tag -> 次数/耗时
|
||
|
||
unsigned long long nRegionTexts; // 一共恢复过多少份 SAT 文本
|
||
size_t nUniqueHashes; // 其中不同内容有多少
|
||
unsigned long long nSimulatedHits; // 若做内容缓存，能命中多少次
|
||
bool bHashTableOverflow;
|
||
|
||
std::set<unsigned long long> hashSeen;
|
||
|
||
unsigned long long nTempFiles; // 临时文件写入次数
|
||
unsigned long long nTempFileBytes; // 临时文件累计字节
|
||
|
||
unsigned long long nWriteBacks; // Region -> SAT 文本 次数
|
||
|
||
// 属性 key：class 名 -> 唯一/命中统计
|
||
std::map<std::string, KeyStat> attrStats;
|
||
|
||
// 延迟建几何：tag -> 统计
|
||
std::map<std::string, EnsureStat> ensureStats;
|
||
|
||
// 回写次数：实体类 -> 次数
|
||
std::map<std::string, unsigned long long> writeBackByClass;
|
||
};
|
||
|
||
// 故意用函数内 static：AGENTS.md 禁止文件级 static。
|
||
// CoreLibrary 是静态库且只被 CoreCommand 链接，
|
||
// 所以这里的实例在 CoreCommand.arx 里是唯一的一份。
|
||
Stats& GetStats()
|
||
{
|
||
static Stats s_stats;
|
||
if (!s_stats.bInited)
|
||
{
|
||
s_stats.bInited = true;
|
||
#ifndef NDEBUG
|
||
const char* psz = ::getenv("AEC_PERF_COUNTER");
|
||
s_stats.bEnabled = (psz != NULL && psz[0] != '\0' && psz[0] != '0');
|
||
#else
|
||
s_stats.bEnabled = false;
|
||
#endif
|
||
}
|
||
return s_stats;
|
||
}
|
||
|
||
long long NowTicks()
|
||
{
|
||
LARGE_INTEGER li;
|
||
::QueryPerformanceCounter(&li);
|
||
return (long long)li.QuadPart;
|
||
}
|
||
|
||
unsigned long long TicksToUs(long long nTicks)
|
||
{
|
||
static long long nFreq = 0;
|
||
if (nFreq == 0)
|
||
{
|
||
LARGE_INTEGER li;
|
||
if (!::QueryPerformanceFrequency(&li) || li.QuadPart == 0)
|
||
nFreq = 1;
|
||
else
|
||
nFreq = (long long)li.QuadPart;
|
||
}
|
||
if (nTicks <= 0)
|
||
return 0;
|
||
return (unsigned long long)((nTicks * 1000000LL) / nFreq);
|
||
}
|
||
|
||
// FNV-1a 64
|
||
unsigned long long Hash64(const char* pszTxt, size_t nLen)
|
||
{
|
||
unsigned long long h = 1469598103934665603ULL;
|
||
for (size_t i = 0; i < nLen; ++i)
|
||
{
|
||
h ^= (unsigned char)pszTxt[i];
|
||
h *= 1099511628211ULL;
|
||
}
|
||
return h;
|
||
}
|
||
|
||
Entry& GetEntry(const char* pszTag)
|
||
{
|
||
Stats& s = GetStats();
|
||
std::string key(pszTag ? pszTag : "?");
|
||
return s.entries[key];
|
||
}
|
||
|
||
std::string TempReportPath()
|
||
{
|
||
char szTmp[MAX_PATH + 1];
|
||
::memset(szTmp, 0, sizeof(szTmp));
|
||
DWORD n = ::GetTempPathA(MAX_PATH, szTmp);
|
||
if (n == 0 || n >= MAX_PATH)
|
||
return std::string("aec_section_perf.txt");
|
||
std::string s(szTmp);
|
||
s += "aec_section_perf.txt";
|
||
return s;
|
||
}
|
||
}
|
||
|
||
namespace SectionPerf
|
||
{
|
||
bool Enabled()
|
||
{
|
||
return GetStats().bEnabled;
|
||
}
|
||
|
||
Scope::Scope(const char* pszTag)
|
||
: m_pszTag(pszTag), m_nStart(0), m_bActive(false)
|
||
{
|
||
if (!GetStats().bEnabled)
|
||
return;
|
||
m_bActive = true;
|
||
m_nStart = NowTicks();
|
||
}
|
||
|
||
Scope::~Scope()
|
||
{
|
||
if (!m_bActive)
|
||
return;
|
||
|
||
const unsigned long long nUs = TicksToUs(NowTicks() - m_nStart);
|
||
Entry& e = GetEntry(m_pszTag);
|
||
++e.nCount;
|
||
e.nTotalUs += nUs;
|
||
if (nUs > e.nMaxUs)
|
||
e.nMaxUs = nUs;
|
||
}
|
||
|
||
void NoteRegionText(const char* pszTxt, size_t nLen)
|
||
{
|
||
Stats& s = GetStats();
|
||
if (!s.bEnabled)
|
||
return;
|
||
if (pszTxt == NULL || nLen == 0)
|
||
return;
|
||
|
||
++s.nRegionTexts;
|
||
|
||
const unsigned long long h = SectionRegionCache::HashSatText(pszTxt, nLen);
|
||
if (s.hashSeen.find(h) != s.hashSeen.end())
|
||
{
|
||
++s.nSimulatedHits;
|
||
return;
|
||
}
|
||
if (s.hashSeen.size() < kMaxUniqueHash)
|
||
{
|
||
s.hashSeen.insert(h);
|
||
++s.nUniqueHashes;
|
||
}
|
||
else
|
||
{
|
||
s.bHashTableOverflow = true;
|
||
}
|
||
}
|
||
|
||
void NoteTempFile(size_t nBytes)
|
||
{
|
||
Stats& s = GetStats();
|
||
if (!s.bEnabled)
|
||
return;
|
||
++s.nTempFiles;
|
||
s.nTempFileBytes += (unsigned long long)nBytes;
|
||
}
|
||
|
||
void NoteWriteBack(const char* pszTag)
|
||
{
|
||
Stats& s = GetStats();
|
||
if (!s.bEnabled)
|
||
return;
|
||
++s.nWriteBacks;
|
||
(void)pszTag;
|
||
}
|
||
|
||
AttrKey::AttrKey(const TCHAR* pszClass)
|
||
: m_nHash(1469598103934665603ULL), m_bActive(GetStats().bEnabled)
|
||
{
|
||
if (!m_bActive)
|
||
return;
|
||
// CStringA 按当前代码页做宽窄转换；非 UNICODE 构建下直接构造
|
||
CStringA sCls(pszClass != NULL ? pszClass : _T("?"));
|
||
m_sClass = (LPCSTR)sCls;
|
||
Add(m_sClass.data(), m_sClass.size());
|
||
}
|
||
|
||
AttrKey::~AttrKey()
|
||
{
|
||
if (!m_bActive)
|
||
return;
|
||
|
||
// 与 NoteRegionText 相同口径：首次出现记唯一，重复出现记一次“命中”
|
||
KeyStat& st = GetStats().attrStats[m_sClass];
|
||
++st.nTotal;
|
||
if (st.seen.find(m_nHash) != st.seen.end())
|
||
{
|
||
++st.nHits;
|
||
return;
|
||
}
|
||
if (st.seen.size() < kMaxUniqueHash)
|
||
{
|
||
st.seen.insert(m_nHash);
|
||
++st.nUnique;
|
||
}
|
||
else
|
||
{
|
||
st.bOverflow = true;
|
||
}
|
||
}
|
||
|
||
void AttrKey::Add(const void* pData, size_t nLen)
|
||
{
|
||
if (!m_bActive || pData == NULL || nLen == 0)
|
||
return;
|
||
const unsigned char* p = (const unsigned char*)pData;
|
||
for (size_t i = 0; i < nLen; ++i)
|
||
{
|
||
m_nHash ^= (unsigned long long)p[i];
|
||
m_nHash *= 1099511628211ULL;
|
||
}
|
||
}
|
||
|
||
void NoteWriteBackClass(const char* pszClass)
|
||
{
|
||
Stats& s = GetStats();
|
||
if (!s.bEnabled)
|
||
return;
|
||
std::string key(pszClass != NULL ? pszClass : "?");
|
||
++s.writeBackByClass[key];
|
||
}
|
||
|
||
void NoteEnsure(const char* pszTag, const void* pObj, bool bRebuilt)
|
||
{
|
||
Stats& s = GetStats();
|
||
if (!s.bEnabled)
|
||
return;
|
||
std::string key(pszTag != NULL ? pszTag : "?");
|
||
EnsureStat& st = s.ensureStats[key];
|
||
++st.nTotal;
|
||
if (bRebuilt)
|
||
{
|
||
++st.nRebuilds;
|
||
++st.builds[pObj];
|
||
}
|
||
else
|
||
{
|
||
++st.nHits;
|
||
}
|
||
}
|
||
|
||
void Dump()
|
||
{
|
||
Stats& s = GetStats();
|
||
if (!s.bEnabled)
|
||
{
|
||
acutPrintf(_T("\n[SectionPerf] not enabled: set AEC_PERF_COUNTER=1 before starting CAD (Debug build only)."));
|
||
return;
|
||
}
|
||
|
||
// 报告正文全 ASCII：控制台用 %hs 直出，落文件也直接可读
|
||
std::string out;
|
||
char szLine[1024];
|
||
|
||
out += "\n================ SectionPerf (Phase 0) ================\n";
|
||
|
||
sprintf_s(szLine, sizeof(szLine), "RegionTexts=%llu UniqueHashes=%llu SimulatedHits=%llu HitRate=%.1f%%\n",
|
||
s.nRegionTexts, (unsigned long long)s.nUniqueHashes, s.nSimulatedHits,
|
||
s.nRegionTexts ? (100.0 * (double)s.nSimulatedHits / (double)s.nRegionTexts) : 0.0);
|
||
out += szLine;
|
||
if (s.bHashTableOverflow)
|
||
out += " (hash table capped: UniqueHashes is under-counted, HitRate over-estimated)\n";
|
||
|
||
sprintf_s(szLine, sizeof(szLine), "TempFiles=%llu TempBytes=%llu WriteBacks=%llu\n",
|
||
s.nTempFiles, s.nTempFileBytes, s.nWriteBacks);
|
||
out += szLine;
|
||
|
||
if (!s.ensureStats.empty())
|
||
{
|
||
out += "---- lazy-create cache (by tag) ----\n";
|
||
out += " tag total hits rebuild hit_rate objects built_once built_2_3 built_4p\n";
|
||
for (std::map<std::string, EnsureStat>::const_iterator it = s.ensureStats.begin();
|
||
it != s.ensureStats.end(); ++it)
|
||
{
|
||
const EnsureStat& e = it->second;
|
||
int nOnce = 0, n23 = 0, n4p = 0;
|
||
for (std::map<const void*, int>::const_iterator b = e.builds.begin(); b != e.builds.end(); ++b)
|
||
{
|
||
if (b->second <= 1) ++nOnce;
|
||
else if (b->second <= 3) ++n23;
|
||
else ++n4p;
|
||
}
|
||
const double rate = e.nTotal ? (100.0 * (double)e.nHits / (double)e.nTotal) : 0.0;
|
||
sprintf_s(szLine, sizeof(szLine), " %-12s %-9llu %-7llu %-8llu %7.1f%% %-7llu %-11d %-10d %d\n",
|
||
it->first.c_str(), e.nTotal, e.nHits, e.nRebuilds, rate,
|
||
(unsigned long long)e.builds.size(), nOnce, n23, n4p);
|
||
out += szLine;
|
||
// top offenders：被重建次数最多的对象
|
||
const void* pWorst = NULL; int nWorst = 0;
|
||
for (std::map<const void*, int>::const_iterator b = e.builds.begin(); b != e.builds.end(); ++b)
|
||
{
|
||
if (b->second > nWorst) { nWorst = b->second; pWorst = b->first; }
|
||
}
|
||
if (nWorst > 3)
|
||
{
|
||
sprintf_s(szLine, sizeof(szLine), " worst object %p rebuilt %d times\n", pWorst, nWorst);
|
||
out += szLine;
|
||
}
|
||
}
|
||
}
|
||
|
||
if (!s.writeBackByClass.empty())
|
||
{
|
||
out += "---- write-backs by entity class ----\n";
|
||
out += " count class\n";
|
||
for (std::map<std::string, unsigned long long>::const_iterator it = s.writeBackByClass.begin();
|
||
it != s.writeBackByClass.end(); ++it)
|
||
{
|
||
sprintf_s(szLine, sizeof(szLine), " %-8llu %s\n", it->second, it->first.c_str());
|
||
out += szLine;
|
||
}
|
||
}
|
||
|
||
if (!s.attrStats.empty())
|
||
{
|
||
out += "---- attr key (by class, would-be cache hit rate) ----\n";
|
||
out += " total unique hits hit_rate class\n";
|
||
for (std::map<std::string, KeyStat>::const_iterator it = s.attrStats.begin();
|
||
it != s.attrStats.end(); ++it)
|
||
{
|
||
const KeyStat& k = it->second;
|
||
const double rate = k.nTotal ? (100.0 * (double)k.nHits / (double)k.nTotal) : 0.0;
|
||
sprintf_s(szLine, sizeof(szLine), " %-8llu %-9llu %-6llu %7.1f%% %s%s\n",
|
||
k.nTotal, (unsigned long long)k.nUnique, k.nHits, rate,
|
||
it->first.c_str(), k.bOverflow ? " (capped)" : "");
|
||
out += szLine;
|
||
}
|
||
}
|
||
|
||
out += "---- timing (by tag) ----\n";
|
||
out += " count total_ms avg_us max_us tag\n";
|
||
for (std::map<std::string, Entry>::const_iterator it = s.entries.begin();
|
||
it != s.entries.end(); ++it)
|
||
{
|
||
const Entry& e = it->second;
|
||
const double avgUs = e.nCount ? ((double)e.nTotalUs / (double)e.nCount) : 0.0;
|
||
sprintf_s(szLine, sizeof(szLine), " %-9llu %10.1f %10.1f %10llu %s\n",
|
||
e.nCount, (double)e.nTotalUs / 1000.0, avgUs, e.nMaxUs, it->first.c_str());
|
||
out += szLine;
|
||
}
|
||
out += "=======================================================\n";
|
||
|
||
// 逐行输出：%hs 把窄字符串塞进 TCHAR 格式串，不涉及宽字符转换
|
||
const char* psz = out.c_str();
|
||
while (*psz != '\0')
|
||
{
|
||
const char* pszEnd = strchr(psz, '\n');
|
||
const size_t nSeg = (pszEnd != NULL) ? (size_t)(pszEnd - psz) : strlen(psz);
|
||
if (nSeg > 0 && nSeg < sizeof(szLine))
|
||
{
|
||
memcpy(szLine, psz, nSeg);
|
||
szLine[nSeg] = '\0';
|
||
acutPrintf(_T("\n%hs"), szLine);
|
||
}
|
||
if (pszEnd == NULL)
|
||
break;
|
||
psz = pszEnd + 1;
|
||
}
|
||
|
||
// 同时落文件，方便事后拿去做分析
|
||
const std::string sPath = TempReportPath();
|
||
FILE* fp = NULL;
|
||
if (fopen_s(&fp, sPath.c_str(), "a") == 0 && fp != NULL)
|
||
{
|
||
fprintf(fp, "%s", out.c_str());
|
||
fclose(fp);
|
||
}
|
||
}
|
||
|
||
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;
|
||
}
|
||
// 写到独立文件：不打扰 ENVIPERFDUMP 的报告文件（脚本靠它判断就绪）
|
||
{
|
||
char szTmp[MAX_PATH + 1];
|
||
::memset(szTmp, 0, sizeof(szTmp));
|
||
if (::GetTempPathA(MAX_PATH, szTmp) != 0)
|
||
{
|
||
std::string sPath(szTmp);
|
||
sPath += "aec_writeback_trace.txt";
|
||
FILE* fp = NULL;
|
||
if (fopen_s(&fp, sPath.c_str(), "ab") == 0 && fp != NULL)
|
||
{
|
||
fprintf(fp, "%s", out.c_str());
|
||
fclose(fp);
|
||
}
|
||
}
|
||
}
|
||
}
|
||
|
||
void AppendReport(const char* pszText)
|
||
{
|
||
if (pszText == NULL)
|
||
return;
|
||
const std::string sPath = TempReportPath();
|
||
FILE* fp = NULL;
|
||
if (fopen_s(&fp, sPath.c_str(), "a") == 0 && fp != NULL)
|
||
{
|
||
fprintf(fp, "%s", pszText);
|
||
if (pszText[0] != 0 && pszText[strlen(pszText)-1] != '\n')
|
||
fprintf(fp, "%s", "\n");
|
||
fclose(fp);
|
||
}
|
||
}
|
||
void Reset()
|
||
{
|
||
Stats& s = GetStats();
|
||
s.entries.clear();
|
||
s.hashSeen.clear();
|
||
s.nRegionTexts = 0;
|
||
s.nUniqueHashes = 0;
|
||
s.nSimulatedHits = 0;
|
||
s.bHashTableOverflow = false;
|
||
s.nTempFiles = 0;
|
||
s.nTempFileBytes = 0;
|
||
s.nWriteBacks = 0;
|
||
s.attrStats.clear();
|
||
s.writeBackByClass.clear();
|
||
s.ensureStats.clear();
|
||
}
|
||
}
|