Skip to content

Commit

Permalink
Improve ENC logging. (dotnet#53695)
Browse files Browse the repository at this point in the history 
Fix assert in CMiniMdRW::GetTableForToken.  g_TblIndex entries for MethodImpl and NestedClass needed token values.
  • Loading branch information
@mikem8361
mikem8361 authored Jun 3, 2021
1 parent e218d8e commit 4fd2db9
Show file tree
Hide file tree
Showing 5 changed files with 41 additions and 40 deletions.
34 changes: 17 additions & 17 deletions src/coreclr/gc/objecthandle.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
}
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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)));
}
}

Expand Down
1 change: 1 addition & 0 deletions src/coreclr/inc/corhdr.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1498,6 +1498,7 @@ typedef enum CorTokenType
mdtFile = 0x26000000, //
mdtExportedType = 0x27000000, //
mdtManifestResource = 0x28000000, //
mdtNestedClass = 0x29000000, //
mdtGenericParam = 0x2a000000, //
mdtMethodSpec = 0x2b000000, //
mdtGenericParamConstraint = 0x2c000000,
Expand Down
4 changes: 2 additions & 2 deletions src/coreclr/md/enc/metamodelrw.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 <TODO>@FUTURE: Check that these are the right entries here.</TODO>
Expand All @@ -280,7 +280,7 @@ const TblIndex g_TblIndex[TBL_COUNT] =
{(ULONG) -1, (ULONG) -1, mdtFile}, // File <TODO>@FUTURE: Update with the right number.</TODO>
{(ULONG) -1, (ULONG) -1, mdtExportedType}, // ExportedType <TODO>@FUTURE: Update with the right number.</TODO>
{(ULONG) -1, (ULONG) -1, mdtManifestResource},// ManifestResource <TODO>@FUTURE: Update with the right number.</TODO>
{(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
Expand Down
2 changes: 1 addition & 1 deletion src/coreclr/vm/class.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
40 changes: 20 additions & 20 deletions src/coreclr/vm/encee.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand All @@ -68,15 +68,15 @@ 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);
}

// Called when the module is being destroyed (eg. AD unload time)
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();
Expand Down Expand Up @@ -211,22 +211,22 @@ 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;
IfFailGo(pMDImport->GetMethodImplProps(token, &dwMethodRVA, &dwMethodFlags));

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);
}

Expand All @@ -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))
{
Expand Down Expand Up @@ -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;
}

Expand All @@ -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);
Expand All @@ -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;
}

Expand All @@ -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));
}
}

Expand Down Expand Up @@ -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;
}

Expand All @@ -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;
}

Expand All @@ -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));
}
}

Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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.
Expand Down

0 comments on commit 4fd2db9

Please sign in to comment.