From 4fd2db96d5607752b69763f0b095446c971ab7f1 Mon Sep 17 00:00:00 2001 From: Mike McLaughlin Date: Thu, 3 Jun 2021 15:02:51 -0700 Subject: [PATCH] Improve ENC logging. (#53695) Fix assert in CMiniMdRW::GetTableForToken. g_TblIndex entries for MethodImpl and NestedClass needed token values. --- src/coreclr/gc/objecthandle.cpp | 34 ++++++++++++++++---------------- src/coreclr/inc/corhdr.h | 1 + src/coreclr/md/enc/metamodelrw.cpp | 4 ++-- src/coreclr/vm/class.cpp | 2 +- src/coreclr/vm/encee.cpp | 40 +++++++++++++++++++------------------- 5 files changed, 41 insertions(+), 40 deletions(-) diff --git a/src/coreclr/gc/objecthandle.cpp b/src/coreclr/gc/objecthandle.cpp index 208689b..1485f56 100644 --- a/src/coreclr/gc/objecthandle.cpp +++ b/src/coreclr/gc/objecthandle.cpp @@ -151,9 +151,9 @@ void CALLBACK UpdateDependentHandle(_UNCHECKED_OBJECTREF *pObjRef, uintptr_t *pE Object **pPrimaryRef = (Object **)pObjRef; Object **pSecondaryRef = (Object **)pExtraInfo; - LOG((LF_GC|LF_ENC, LL_INFO10000, LOG_HANDLE_OBJECT("Querying for new location of ", + LOG((LF_GC, LL_INFO10000, LOG_HANDLE_OBJECT("Querying for new location of ", pPrimaryRef, "to ", *pPrimaryRef))); - LOG((LF_GC|LF_ENC, LL_INFO10000, LOG_HANDLE_OBJECT(" and ", + LOG((LF_GC, LL_INFO10000, LOG_HANDLE_OBJECT(" and ", pSecondaryRef, "to ", *pSecondaryRef))); #ifdef _DEBUG @@ -168,16 +168,16 @@ void CALLBACK UpdateDependentHandle(_UNCHECKED_OBJECTREF *pObjRef, uintptr_t *pE #ifdef _DEBUG if (pOldPrimary != *pPrimaryRef) - LOG((LF_GC|LF_ENC, LL_INFO10000, "Updating " FMT_HANDLE "from" FMT_ADDR "to " FMT_OBJECT "\n", + LOG((LF_GC, LL_INFO10000, "Updating " FMT_HANDLE "from" FMT_ADDR "to " FMT_OBJECT "\n", DBG_ADDR(pPrimaryRef), DBG_ADDR(pOldPrimary), DBG_ADDR(*pPrimaryRef))); else - LOG((LF_GC|LF_ENC, LL_INFO10000, "Updating " FMT_HANDLE "- " FMT_OBJECT "did not move\n", + LOG((LF_GC, LL_INFO10000, "Updating " FMT_HANDLE "- " FMT_OBJECT "did not move\n", DBG_ADDR(pPrimaryRef), DBG_ADDR(*pPrimaryRef))); if (pOldSecondary != *pSecondaryRef) - LOG((LF_GC|LF_ENC, LL_INFO10000, "Updating " FMT_HANDLE "from" FMT_ADDR "to " FMT_OBJECT "\n", + LOG((LF_GC, LL_INFO10000, "Updating " FMT_HANDLE "from" FMT_ADDR "to " FMT_OBJECT "\n", DBG_ADDR(pSecondaryRef), DBG_ADDR(pOldSecondary), DBG_ADDR(*pSecondaryRef))); else - LOG((LF_GC|LF_ENC, LL_INFO10000, "Updating " FMT_HANDLE "- " FMT_OBJECT "did not move\n", + LOG((LF_GC, LL_INFO10000, "Updating " FMT_HANDLE "- " FMT_OBJECT "did not move\n", DBG_ADDR(pSecondaryRef), DBG_ADDR(*pSecondaryRef))); #endif } @@ -189,9 +189,9 @@ void CALLBACK PromoteDependentHandle(_UNCHECKED_OBJECTREF *pObjRef, uintptr_t *p Object **pPrimaryRef = (Object **)pObjRef; Object **pSecondaryRef = (Object **)pExtraInfo; - LOG((LF_GC|LF_ENC, LL_INFO1000, "Checking promotion of DependentHandle")); - LOG((LF_GC|LF_ENC, LL_INFO1000, LOG_HANDLE_OBJECT_CLASS("\tPrimary:\t", pObjRef, "to ", *pObjRef))); - LOG((LF_GC|LF_ENC, LL_INFO1000, LOG_HANDLE_OBJECT_CLASS("\tSecondary\t", pSecondaryRef, "to ", *pSecondaryRef))); + LOG((LF_GC, LL_INFO1000, "Checking promotion of DependentHandle\n")); + LOG((LF_GC, LL_INFO1000, LOG_HANDLE_OBJECT_CLASS("\tPrimary:\t", pObjRef, "to ", *pObjRef))); + LOG((LF_GC, LL_INFO1000, LOG_HANDLE_OBJECT_CLASS("\tSecondary\t", pSecondaryRef, "to ", *pSecondaryRef))); ScanContext *sc = (ScanContext*)lp1; DhContext *pDhContext = Ref_GetDependentHandleContext(sc); @@ -200,7 +200,7 @@ void CALLBACK PromoteDependentHandle(_UNCHECKED_OBJECTREF *pObjRef, uintptr_t *p { if (!g_theGCHeap->IsPromoted(*pSecondaryRef)) { - LOG((LF_GC|LF_ENC, LL_INFO10000, "\tPromoting secondary " LOG_OBJECT_CLASS(*pSecondaryRef))); + LOG((LF_GC, LL_INFO10000, "\tPromoting secondary " LOG_OBJECT_CLASS(*pSecondaryRef))); _ASSERTE(lp2); promote_func* callback = (promote_func*) lp2; callback(pSecondaryRef, (ScanContext *)lp1, 0); @@ -227,22 +227,22 @@ void CALLBACK ClearDependentHandle(_UNCHECKED_OBJECTREF *pObjRef, uintptr_t *pEx Object **pPrimaryRef = (Object **)pObjRef; Object **pSecondaryRef = (Object **)pExtraInfo; - LOG((LF_GC|LF_ENC, LL_INFO1000, "Checking referent of DependentHandle")); - LOG((LF_GC|LF_ENC, LL_INFO1000, LOG_HANDLE_OBJECT_CLASS("\tPrimary:\t", pPrimaryRef, "to ", *pPrimaryRef))); - LOG((LF_GC|LF_ENC, LL_INFO1000, LOG_HANDLE_OBJECT_CLASS("\tSecondary\t", pSecondaryRef, "to ", *pSecondaryRef))); + LOG((LF_GC, LL_INFO1000, "Checking referent of DependentHandle")); + LOG((LF_GC, LL_INFO1000, LOG_HANDLE_OBJECT_CLASS("\tPrimary:\t", pPrimaryRef, "to ", *pPrimaryRef))); + LOG((LF_GC, LL_INFO1000, LOG_HANDLE_OBJECT_CLASS("\tSecondary\t", pSecondaryRef, "to ", *pSecondaryRef))); if (!g_theGCHeap->IsPromoted(*pPrimaryRef)) { - LOG((LF_GC|LF_ENC, LL_INFO1000, "\tunreachable ", LOG_OBJECT_CLASS(*pPrimaryRef))); - LOG((LF_GC|LF_ENC, LL_INFO1000, "\tunreachable ", LOG_OBJECT_CLASS(*pSecondaryRef))); + LOG((LF_GC, LL_INFO1000, "\tunreachable ", LOG_OBJECT_CLASS(*pPrimaryRef))); + LOG((LF_GC, LL_INFO1000, "\tunreachable ", LOG_OBJECT_CLASS(*pSecondaryRef))); *pPrimaryRef = NULL; *pSecondaryRef = NULL; } else { _ASSERTE(g_theGCHeap->IsPromoted(*pSecondaryRef)); - LOG((LF_GC|LF_ENC, LL_INFO10000, "\tPrimary is reachable " LOG_OBJECT_CLASS(*pPrimaryRef))); - LOG((LF_GC|LF_ENC, LL_INFO10000, "\tSecondary is reachable " LOG_OBJECT_CLASS(*pSecondaryRef))); + LOG((LF_GC, LL_INFO10000, "\tPrimary is reachable " LOG_OBJECT_CLASS(*pPrimaryRef))); + LOG((LF_GC, LL_INFO10000, "\tSecondary is reachable " LOG_OBJECT_CLASS(*pSecondaryRef))); } } diff --git a/src/coreclr/inc/corhdr.h b/src/coreclr/inc/corhdr.h index de3e95d..ecefcef 100644 --- a/src/coreclr/inc/corhdr.h +++ b/src/coreclr/inc/corhdr.h @@ -1498,6 +1498,7 @@ typedef enum CorTokenType mdtFile = 0x26000000, // mdtExportedType = 0x27000000, // mdtManifestResource = 0x28000000, // + mdtNestedClass = 0x29000000, // mdtGenericParam = 0x2a000000, // mdtMethodSpec = 0x2b000000, // mdtGenericParamConstraint = 0x2c000000, diff --git a/src/coreclr/md/enc/metamodelrw.cpp b/src/coreclr/md/enc/metamodelrw.cpp index 4a849af..5f62e5f 100644 --- a/src/coreclr/md/enc/metamodelrw.cpp +++ b/src/coreclr/md/enc/metamodelrw.cpp @@ -264,7 +264,7 @@ const TblIndex g_TblIndex[TBL_COUNT] = {(ULONG) -1, (ULONG) -1, (ULONG) -1}, // PropertyPtr {(ULONG) -1, (ULONG) -1, mdtProperty}, // Property {(ULONG) -1, (ULONG) -1, (ULONG) -1}, // MethodSemantics - {(ULONG) -1, (ULONG) -1, (ULONG) -1}, // MethodImpl + {(ULONG) -1, (ULONG) -1, mdtMethodImpl}, // MethodImpl {(ULONG) -1, (ULONG) -1, mdtModuleRef}, // ModuleRef {(ULONG) -1, (ULONG) -1, mdtTypeSpec}, // TypeSpec {(ULONG) -1, (ULONG) -1, (ULONG) -1}, // ImplMap @FUTURE: Check that these are the right entries here. @@ -280,7 +280,7 @@ const TblIndex g_TblIndex[TBL_COUNT] = {(ULONG) -1, (ULONG) -1, mdtFile}, // File @FUTURE: Update with the right number. {(ULONG) -1, (ULONG) -1, mdtExportedType}, // ExportedType @FUTURE: Update with the right number. {(ULONG) -1, (ULONG) -1, mdtManifestResource},// ManifestResource @FUTURE: Update with the right number. - {(ULONG) -1, (ULONG) -1, (ULONG) -1}, // NestedClass + {(ULONG) -1, (ULONG) -1, mdtNestedClass}, // NestedClass {(ULONG) -1, (ULONG) -1, mdtGenericParam}, // GenericParam {(ULONG) -1, (ULONG) -1, mdtMethodSpec}, // MethodSpec {(ULONG) -1, (ULONG) -1, mdtGenericParamConstraint},// GenericParamConstraint diff --git a/src/coreclr/vm/class.cpp b/src/coreclr/vm/class.cpp index 80a7024..17417e0 100644 --- a/src/coreclr/vm/class.cpp +++ b/src/coreclr/vm/class.cpp @@ -274,7 +274,7 @@ VOID EEClass::FixupFieldDescForEnC(MethodTable * pMT, EnCFieldDesc *pFD, mdField { szFieldName = "Invalid FieldDef record"; } - LOG((LF_ENC, LL_INFO100, "EEClass::InitializeFieldDescForEnC %s\n", szFieldName)); + LOG((LF_ENC, LL_INFO100, "EEClass::FixupFieldDescForEnC %08x %s\n", fieldDef, szFieldName)); } #endif //LOGGING diff --git a/src/coreclr/vm/encee.cpp b/src/coreclr/vm/encee.cpp index ca9e16d..64a006f 100644 --- a/src/coreclr/vm/encee.cpp +++ b/src/coreclr/vm/encee.cpp @@ -46,7 +46,7 @@ EditAndContinueModule::EditAndContinueModule(Assembly *pAssembly, mdToken module } CONTRACTL_END - LOG((LF_ENC,LL_INFO100,"EACM::ctor 0x%x\n", this)); + LOG((LF_ENC,LL_INFO100,"EACM::ctor %p\n", this)); m_applyChangesCount = CorDB_DEFAULT_ENC_FUNCTION_VERSION; } @@ -68,7 +68,7 @@ void EditAndContinueModule::Initialize(AllocMemTracker *pamTracker, LPCWSTR szNa } CONTRACTL_END - LOG((LF_ENC,LL_INFO100,"EACM::Initialize 0x%x\n", this)); + LOG((LF_ENC,LL_INFO100,"EACM::Initialize %p\n", this)); Module::Initialize(pamTracker, szName); } @@ -76,7 +76,7 @@ void EditAndContinueModule::Initialize(AllocMemTracker *pamTracker, LPCWSTR szNa void EditAndContinueModule::Destruct() { LIMITED_METHOD_CONTRACT; - LOG((LF_ENC,LL_EVERYTHING,"EACM::Destruct 0x%x\n", this)); + LOG((LF_ENC,LL_EVERYTHING,"EACM::Destruct %p\n", this)); // Call the superclass's Destruct method... Module::Destruct(); @@ -211,14 +211,14 @@ HRESULT EditAndContinueModule::ApplyEditAndContinue( mdToken token; while (pIMDInternalImportENC->EnumNext(&enumENC, &token)) { - STRESS_LOG3(LF_ENC, LL_INFO100, "EACM::AEAC: updated token 0x%x; type 0x%x; rid 0x%x\n", token, TypeFromToken(token), RidFromToken(token)); + STRESS_LOG3(LF_ENC, LL_INFO100, "EACM::AEAC: updated token %08x; type %08x; rid %08x\n", token, TypeFromToken(token), RidFromToken(token)); switch (TypeFromToken(token)) { case mdtMethodDef: // MethodDef token - update/add a method - LOG((LF_ENC, LL_INFO10000, "EACM::AEAC: Found method 0x%x\n", token)); + LOG((LF_ENC, LL_INFO10000, "EACM::AEAC: Found method %08x\n", token)); ULONG dwMethodRVA; DWORD dwMethodFlags; @@ -226,7 +226,7 @@ HRESULT EditAndContinueModule::ApplyEditAndContinue( if (dwMethodRVA >= cbDeltaIL) { - LOG((LF_ENC, LL_INFO10000, "EACM::AEAC: failure RVA of %d with cbDeltaIl %d\n", dwMethodRVA, cbDeltaIL)); + LOG((LF_ENC, LL_INFO10000, "EACM::AEAC: Failure RVA of %d with cbDeltaIl %d\n", dwMethodRVA, cbDeltaIL)); IfFailGo(E_INVALIDARG); } @@ -251,7 +251,7 @@ HRESULT EditAndContinueModule::ApplyEditAndContinue( case mdtFieldDef: // FieldDef token - add a new field - LOG((LF_ENC, LL_INFO10000, "EACM::AEAC: Found field 0x%x\n", token)); + LOG((LF_ENC, LL_INFO10000, "EACM::AEAC: Found field %08x\n", token)); if (LookupFieldDef(token)) { @@ -367,7 +367,7 @@ HRESULT EditAndContinueModule::AddMethod(mdMethodDef token) HRESULT hr = GetMDImport()->GetParentToken(token, &parentTypeDef); if (FAILED(hr)) { - LOG((LF_ENC, LL_INFO100, "**Error** EnCModule::AM can't find parent token for method token %p\n", token)); + LOG((LF_ENC, LL_INFO100, "**Error** EnCModule::AM can't find parent token for method token %08x\n", token)); return E_FAIL; } @@ -377,7 +377,7 @@ HRESULT EditAndContinueModule::AddMethod(mdMethodDef token) { // Class isn't loaded yet, don't have to modify any existing EE data structures beyond the metadata. // Just notify debugger and return. - LOG((LF_ENC, LL_INFO100, "EnCModule::AM class %p not loaded, our work is done\n", parentTypeDef)); + LOG((LF_ENC, LL_INFO100, "EnCModule::AM class %08x not loaded (method %08x), our work is done\n", parentTypeDef, token)); if (CORDebuggerAttached()) { hr = g_pDebugInterface->UpdateNotYetLoadedFunction(token, this, m_applyChangesCount); @@ -386,14 +386,14 @@ HRESULT EditAndContinueModule::AddMethod(mdMethodDef token) } // Add the method to the runtime's Class data structures - LOG((LF_ENC, LL_INFO100000, "EACM::AM: Adding function %p\n", token)); + LOG((LF_ENC, LL_INFO100000, "EACM::AM: Adding function %08x to type %08x\n", token, parentTypeDef)); MethodDesc *pMethod = NULL; hr = EEClass::AddMethod(pParentType, token, 0, &pMethod); if (FAILED(hr)) { _ASSERTE(!"Failed to add function"); - LOG((LF_ENC, LL_INFO100000, "**Error** EACM::AM: Failed to add function %p with hr 0x%x\n", token)); + LOG((LF_ENC, LL_INFO100000, "**Error** EACM::AM: Failed to add function %08x with hr %08x\n", token, hr)); return hr; } @@ -404,7 +404,7 @@ HRESULT EditAndContinueModule::AddMethod(mdMethodDef token) if (FAILED(hr)) { _ASSERTE(!"Failed to add function"); - LOG((LF_ENC, LL_INFO100000, "**Error** EACM::AF: Failed to add method %p to debugger with hr 0x%x\n", token)); + LOG((LF_ENC, LL_INFO100000, "**Error** EACM::AF: Failed to add method %08x to debugger with hr %08x\n", token, hr)); } } @@ -444,7 +444,7 @@ HRESULT EditAndContinueModule::AddField(mdFieldDef token) if (FAILED(hr)) { - LOG((LF_ENC, LL_INFO100, "**Error** EnCModule::AF can't find parent token for field token %p\n", token)); + LOG((LF_ENC, LL_INFO100, "**Error** EnCModule::AF can't find parent token for field token %08x\n", token)); return E_FAIL; } @@ -456,18 +456,18 @@ HRESULT EditAndContinueModule::AddField(mdFieldDef token) MethodTable * pParentType = LookupTypeDef(parentTypeDef).AsMethodTable(); if (pParentType == NULL) { - LOG((LF_ENC, LL_INFO100, "EnCModule::AF class %p not loaded, our work is done\n", parentTypeDef)); + LOG((LF_ENC, LL_INFO100, "EnCModule::AF class %08x not loaded (field %08x), our work is done\n", parentTypeDef, token)); return S_OK; } // Create a new EnCFieldDesc for the field and add it to the class - LOG((LF_ENC, LL_INFO100000, "EACM::AM: Adding field %p\n", token)); + LOG((LF_ENC, LL_INFO100000, "EACM::AM: Adding field %08x to type %08x\n", token, parentTypeDef)); EnCFieldDesc *pField; hr = EEClass::AddField(pParentType, token, &pField); if (FAILED(hr)) { - LOG((LF_ENC, LL_INFO100000, "**Error** EACM::AF: Failed to add field %p to EE with hr 0x%x\n", token)); + LOG((LF_ENC, LL_INFO100000, "**Error** EACM::AF: Failed to add field %08x to EE with hr %08x\n", token, hr)); return hr; } @@ -477,7 +477,7 @@ HRESULT EditAndContinueModule::AddField(mdFieldDef token) hr = g_pDebugInterface->AddField(pField, m_applyChangesCount); if (FAILED(hr)) { - LOG((LF_ENC, LL_INFO100000, "**Error** EACM::AF: Failed to add field %p to debugger with hr 0x%x\n", token)); + LOG((LF_ENC, LL_INFO100000, "**Error** EACM::AF: Failed to add field %08x to debugger with hr %08x\n", token, hr)); } } @@ -801,7 +801,7 @@ NOINLINE void EditAndContinueModule::FixContextAndResume( // Set the new IP // Note that all we're really doing here is setting the IP register. We unfortunately don't // share any code with the implementation of debugger SetIP, despite the similarities. - LOG((LF_ENC, LL_INFO100, "EnCModule::ResumeInUpdatedFunction: Resume at EIP=0x%x\n", pNewCodeInfo->GetCodeAddress())); + LOG((LF_ENC, LL_INFO100, "EnCModule::ResumeInUpdatedFunction: Resume at EIP=%p\n", pNewCodeInfo->GetCodeAddress())); Thread *pCurThread = GetThread(); pCurThread->SetFilterContext(pContext); @@ -1242,7 +1242,7 @@ PTR_CBYTE EnCSyncBlockInfo::ResolveField(OBJECTREF thisPointer, EnCFieldDesc *pF PTR_EnCAddedField pEntry = NULL; - LOG((LF_ENC, LL_INFO1000, "EnCSBI:RF for this %p, FD %p\n", OBJECTREFToObject(thisPointer), pFD->GetMemberDef())); + LOG((LF_ENC, LL_INFO1000, "EnCSBI:RF for this %p, FD %08x\n", OBJECTREFToObject(thisPointer), pFD->GetMemberDef())); // This list is not synchronized--it hasn't proved a problem, but we could conceivably see race conditions // arise here. @@ -1316,7 +1316,7 @@ PTR_CBYTE EnCSyncBlockInfo::ResolveOrAllocateField(OBJECTREF thisPointer, EnCFie // if the field doesn't yet have available storage, we'll have to allocate it. PTR_EnCAddedField pEntry = NULL; - LOG((LF_ENC, LL_INFO1000, "EnCSBI:RF for this %p, FD %p\n", OBJECTREFToObject(thisPointer), pFD->GetMemberDef())); + LOG((LF_ENC, LL_INFO1000, "EnCSBI:RF for this %p, FD %08x\n", OBJECTREFToObject(thisPointer), pFD->GetMemberDef())); // This list is not synchronized--it hasn't proved a problem, but we could conceivably see race conditions // arise here. -- 2.7.4