Sketch code for file access tracing

roxie/ccd/ccdfile.cpp

@@ -366,8 +366,11 @@ class CRoxieLazyFileIO : implements ILazyFileIO, implements IDelayedFile, public
         {
             try
             {
+                unsigned __int64 startCycles = get_cycles_now();
                 size32_t ret = active->read(pos, len, data);
                 lastAccess = nsTick();
+                if (doTrace(traceAllFileAccess))
+                    queryFileAccessRecorder().noteAccess(fileIdx, pos, len, get_cycles_now()-startCycles, AccessType::AccessTypeDisk );
                 if (cached && !remote)
                     cached->noteRead(fileIdx, pos, ret);
                 return ret;
@@ -1041,7 +1044,9 @@ class CRoxieFileCache : implements IRoxieFileCache, implements ICopyFileProgress
     unsigned trackCache(const char *filename, unsigned channel)
     {
         // NOTE - called from openFile, with crit already held
-        if (!activeCacheReportingBuffer)
+        // This index/info is used to identify the file in the cache warming information and in 
+        // any tracing of file access patterns.
+        if (!activeCacheReportingBuffer && !doTrace(traceAllFileAccess))
             return (unsigned) -1;
         cacheIndexes.append(filename);
         cacheIndexChannels.append(channel);

system/jlib/jthread.cpp

@@ -2776,6 +2776,86 @@ TraceFlags queryDefaultTraceFlags()
 
 //---------------------------
 
+class DummyFileAccessRecorder : public CInterfaceOf<IFileAccessRecorder>
+{
+    virtual void noteAccess(unsigned fileIdx, offset_t page, size32_t len, unsigned __int64 cycles, AccessType type) override {}
+    virtual void flush() override {}
+} dummyFileAccessRecorder;
+
+static thread_local IFileAccessRecorder *threadFileAccessRecorder = nullptr;
+
+class FileAccessRecorder : public CInterfaceOf<IFileAccessRecorder>
+{
+    struct FileAccessRecord
+    {
+        unsigned fileIdx;
+        offset_t page;
+        size32_t len;
+        unsigned __int64 cycles;
+        AccessType type;
+    };
+
+    FileAccessRecord *currentBuffer = nullptr;
+    unsigned numStored = 0;
+    static constexpr unsigned capacity = 1000000;
+public:
+    FileAccessRecorder()
+    {
+        currentBuffer = new FileAccessRecord[capacity];
+    }
+
+    virtual void noteAccess(unsigned fileIdx, offset_t page, size32_t len, unsigned __int64 cycles, AccessType type)
+    {
+        if (numStored == capacity)
+            flush();
+        currentBuffer[numStored].fileIdx = fileIdx;
+        currentBuffer[numStored].page = page;
+        currentBuffer[numStored].len = len;
+        currentBuffer[numStored].cycles = cycles;
+        currentBuffer[numStored].type = type;
+        numStored++;
+    }
+    virtual void flush() override 
+    {
+        // write out the current info to a file, ideally asynchronously. We can allocate a new buffer and return immediately
+        // translate info from cycles to nanoseconds as we do so (and potentially compress the info a bit).
+        numStored = 0;
+    }
+};
+
+// Retrieve file access recorder the active thread. Should never return null 
+static bool releaseFileAccessRecorder(bool isPooled)
+{
+    if (!isPooled)
+    {
+        if (threadFileAccessRecorder && threadFileAccessRecorder != &dummyFileAccessRecorder)
+        {
+            threadFileAccessRecorder->flush();
+            ::Release(threadFileAccessRecorder);
+            threadFileAccessRecorder = nullptr;            
+        }
+        return true;
+    }
+    return false;
+}
+
+IFileAccessRecorder &queryFileAccessRecorder()
+{
+    if (!threadFileAccessRecorder)
+    {
+        if (doTrace(traceAllFileAccess))
+        {
+            threadFileAccessRecorder = new FileAccessRecorder;
+            addThreadTermFunc(releaseFileAccessRecorder);
+        }
+        else
+            threadFileAccessRecorder = &dummyFileAccessRecorder;
+    }
+    return *threadFileAccessRecorder;
+}
+
+//---------------------------
+
 LogContextScope::LogContextScope(const IContextLogger *ctx)
 {
     prevFlags = threadTraceFlags;

system/jlib/jtrace.hpp

@@ -410,6 +410,7 @@ constexpr TraceFlags traceFilters = TraceFlags::flag6;
 constexpr TraceFlags traceKafka = TraceFlags::flag7;
 constexpr TraceFlags traceJava = TraceFlags::flag8;
 constexpr TraceFlags traceOptimizations = TraceFlags::flag9;        // code generator, but IHqlExpressions also used by esp/engines
+constexpr TraceFlags traceAllFileAccess = TraceFlags::flag10;       // roxie, but referenced from jhtree code too
 
 // Specific to Roxie
 constexpr TraceFlags traceRoxieLock = TraceFlags::flag16;
@@ -468,6 +469,7 @@ constexpr std::initializer_list<TraceOption> roxieTraceOptions
     TRACEOPT(traceSmartStepping),
     TRACEOPT(traceAborts),
     TRACEOPT(traceAcknowledge),
+    TRACEOPT(traceAllFileAccess),
 };
 
 constexpr std::initializer_list<TraceOption> eclccTraceOptions
@@ -498,4 +500,21 @@ extern jlib_decl TraceFlags queryDefaultTraceFlags();
 
 extern jlib_decl TraceFlags loadTraceFlags(const IPropertyTree * globals, const std::initializer_list<TraceOption> & y, TraceFlags dft);
 
+// Interface for tracking all file access for subsequent analysis
+
+enum class AccessType : unsigned
+{
+    AccessTypeDisk = 0,
+    AccessTypeNodeCacheLookup = 1,
+};
+
+interface IFileAccessRecorder : public IInterface
+{
+    virtual void noteAccess(unsigned fileIdx, offset_t page, size32_t len, unsigned __int64 cycles, AccessType type) = 0;
+    virtual void flush() = 0;
+};
+
+// Retrieve file access recorder the active thread
+extern jlib_decl IFileAccessRecorder &queryFileAccessRecorder();
+
 #endif