HPCC-10651 Roxie dali cache ineffective on subfiles resolved via package

The cache was holding IResolvedFile objects, but the CResolvedFile for the
superfile was holding on to the IDistributedFile from the subfile, not the
IResolvedFile that contained it, so the subfiles kept getting added to the
cache then removed again as they were released.

Also adds some tracing.

Signed-off-by: Richard Chapman <rchapman@hpccsystems.com>

roxie/ccd/ccddali.cpp

@@ -464,8 +464,7 @@ public:
     {
         if (isConnected)
         {
-            if (traceLevel > 1)
-                DBGLOG("Dali lookup %s", logicalName);
+            unsigned start = msTick();
             CDfsLogicalFileName lfn;
             lfn.set(logicalName);
             Owned<IDistributedFile> dfsFile = queryDistributedFileDirectory().lookup(lfn, userdesc.get(), writeAccess, cacheIt);
@@ -491,7 +490,7 @@ public:
                 writeCache(xpath.str(), xpath.str(), pt);
             }
             if (traceLevel > 1)
-                DBGLOG("Dali lookup %s returned %d", logicalName, dfsFile != NULL);
+                DBGLOG("Dali lookup %s returned %s in %u ms", logicalName, dfsFile != NULL ? "match" : "NO match", msTick()-start);
             return dfsFile.getClear();
         }
         else

roxie/ccd/ccdfile.cpp

@@ -1613,6 +1613,7 @@ protected:
     PointerIArrayOf<IFileDescriptor> remoteSubFiles; // note - on slaves, the file descriptors may have incomplete info. On originating server is always complete
     PointerIArrayOf<IDefRecordMeta> diskMeta;
     IArrayOf<IDistributedFile> subDFiles;  // To make sure subfiles get locked too
+    IArrayOf<IResolvedFile> subRFiles;  // To make sure subfiles get locked too
 
     Owned <IPropertyTree> properties;
 
@@ -1697,7 +1698,9 @@ public:
     virtual void beforeDispose()
     {
         if (cached)
+        {
             cached->removeCache(this);
+        }
     }
     virtual unsigned numSubFiles() const
     {
@@ -2039,8 +2042,7 @@ public:
             assertex(sub->fileType==fileType);
         else
             fileType = sub->fileType;
-        if (sub->dFile)
-            subDFiles.append(*LINK(sub->dFile));
+        subRFiles.append((IResolvedFile &) *LINK(_sub));
         ForEachItemIn(idx, sub->subFiles)
         {
             addFile(sub->subNames.item(idx), LINK(sub->subFiles.item(idx)), LINK(sub->remoteSubFiles.item(idx)));
@@ -2067,6 +2069,8 @@ public:
     {
         if (cached)
         {
+            if (traceLevel > 9)
+                DBGLOG("setCache removing from prior cache %s", queryFileName());
             if (cache==NULL)
                 cached->removeCache(this);
             else

roxie/ccd/ccdstate.cpp

@@ -206,6 +206,8 @@ public:
     virtual void removeCache(const IResolvedFile *file)
     {
         CriticalBlock b(cacheLock);
+        if (traceLevel > 9)
+            DBGLOG("removeCache %s", file->queryFileName());
         // NOTE: it's theoretically possible for the final release to happen after a replacement has been inserted into hash table. 
         // So only remove from hash table if what we find there matches the item that is being deleted.
         IResolvedFile *goer = files.getValue(file->queryFileName());
@@ -223,6 +225,8 @@ public:
             LINK(cache);
             if (cache->isAlive())
                 return cache;
+            if (traceLevel)
+                DBGLOG("Not returning %s from cache as isAlive() returned false", filename);
         }
         return NULL;
     }
@@ -239,7 +243,7 @@ static Owned<KeptLowerCaseAtomTable> daliMisses;
 static void noteDaliMiss(const char *filename)
 {
     CriticalBlock b(daliMissesCrit);
-    if (traceLevel > 4)
+    if (traceLevel > 9)
         DBGLOG("noteDaliMiss %s", filename);
     daliMisses->addAtom(filename);
 }
@@ -248,7 +252,7 @@ static bool checkCachedDaliMiss(const char *filename)
 {
     CriticalBlock b(daliMissesCrit);
     bool ret = daliMisses->find(filename) != NULL;
-    if (traceLevel > 4)
+    if (traceLevel > 9)
         DBGLOG("checkCachedDaliMiss %s returns %d", filename, ret);
     return ret;
 }
@@ -294,9 +298,15 @@ protected:
     static IResolvedFile *resolveLFNusingDaliOrLocal(const char *fileName, bool cacheIt, bool writeAccess, bool alwaysCreate)
     {
         // MORE - look at alwaysCreate... This may be useful to implement earlier locking semantics.
+        if (traceLevel > 9)
+            DBGLOG("resolveLFNusingDaliOrLocal %s %d %d %d", fileName, cacheIt, writeAccess, alwaysCreate);
         IResolvedFile* result = daliFiles.lookupCache(fileName);
         if (result)
+        {
+            if (traceLevel > 9)
+                DBGLOG("resolveLFNusingDaliOrLocal %s - cache hit", fileName);
             return result;
+        }
         if (!checkCachedDaliMiss(fileName))
         {
             Owned<IRoxieDaliHelper> daliHelper = connectToDali();
@@ -343,6 +353,8 @@ protected:
         }
         if (cacheIt)
         {
+            if (traceLevel > 9)
+                DBGLOG("resolveLFNusingDaliOrLocal %s - cache add %d", fileName, result != NULL);
             if (result)
                 daliFiles.addCache(fileName, result);
             else
@@ -388,6 +400,8 @@ protected:
                         // implies that a package file had ~ in subfile names - shouldn;t really, but we allow it (and just strip the ~
                         subFileName.remove(0,1);
                     }
+                    if (traceLevel > 9)
+                        DBGLOG("Looking up subfile %s", subFileName.str());
                     Owned<const IResolvedFile> subFileInfo = lookupExpandedFileName(subFileName, cache, false, false);  // NOTE - overwriting a superfile does NOT require write access to subfiles
                     if (subFileInfo)
                     {