From 55c62dd30748266b95776b70f506de7734073d85 Mon Sep 17 00:00:00 2001 From: baldurk Date: Wed, 26 Aug 2020 12:43:28 +0100 Subject: [PATCH] Serialise timestamps and durations as tick counts, and convert on replay * When we're capturing programs with high-frequency enough API calls, the overhead of the math & extra function calls over Timing::GetTick() is measurable. Removing it and serialising pure tick based durations/timestamps and then converting on replay gives us identical results and saves time while background capturing. --- renderdoc/core/core.cpp | 6 +++ renderdoc/core/core.h | 23 +++++++- renderdoc/driver/d3d11/d3d11_common.h | 11 ++-- renderdoc/driver/d3d12/d3d12_common.h | 13 +++-- renderdoc/driver/gl/gl_common.h | 11 ++-- .../driver/gl/wrappers/gl_debug_funcs.cpp | 18 +++---- renderdoc/driver/vulkan/vk_core.h | 13 +++-- renderdoc/serialise/rdcfile.cpp | 54 +++++++++++++++++-- renderdoc/serialise/rdcfile.h | 3 +- renderdoc/serialise/serialiser.cpp | 14 ++++- renderdoc/serialise/serialiser.h | 7 +++ 11 files changed, 127 insertions(+), 46 deletions(-) diff --git a/renderdoc/core/core.cpp b/renderdoc/core/core.cpp index 993c96001..2be457444 100644 --- a/renderdoc/core/core.cpp +++ b/renderdoc/core/core.cpp @@ -352,8 +352,14 @@ void RenderDoc::Initialise() m_RemoteIdent = 0; m_RemoteThread = 0; + m_TimeBase = 0; + m_TimeFrequency = 1.0; + if(!IsReplayApp()) { + m_TimeBase = Timing::GetTick(); + m_TimeFrequency = Timing::GetTickFrequency() / 1000.0; + Process::ApplyEnvironmentModification(); uint32_t port = RenderDoc_FirstTargetControlPort; diff --git a/renderdoc/core/core.h b/renderdoc/core/core.h index eff7ca2db..51e94d96a 100644 --- a/renderdoc/core/core.h +++ b/renderdoc/core/core.h @@ -410,7 +410,25 @@ public: void Initialise(); void RemoveHooks(); - uint64_t GetMicrosecondTimestamp() { return uint64_t(m_Timer.GetMicroseconds()); } + // these timestamp parameters are set while capturing to the base tick-count and tick frequency of + // the global timer, which will be saved with any new capture to convert timestamps and durations + // in ticks into microseconds. Older captures serialised timestamps and durations as microseconds + // directly. On replay these are set when the capture is first loaded and used to convert any + // serialised timestamps and durations. If an old capture is serialised, they will be set to base + // = 0 and frequency = 1.0 to ensure no conversion happens. + void SetGlobalTimestampParameters(uint64_t base, double frequency) + { + if(IsReplayApp()) + { + m_TimeBase = base; + m_TimeFrequency = frequency; + } + } + void GetGlobalTimestampParameters(uint64_t &base, double &frequency) + { + base = m_TimeBase; + frequency = m_TimeFrequency; + } const GlobalEnvironment &GetGlobalEnvironment() { return m_GlobalEnv; } void InitialiseReplay(GlobalEnvironment env, const rdcarray &args); void ShutdownReplay(); @@ -699,7 +717,8 @@ private: Threading::CriticalSection m_SingleClientLock; rdcstr m_SingleClientName; - PerformanceTimer m_Timer; + uint64_t m_TimeBase; + double m_TimeFrequency; static void TargetControlServerThread(Network::Socket *sock); static void TargetControlClientThread(uint32_t version, Network::Socket *client); diff --git a/renderdoc/driver/d3d11/d3d11_common.h b/renderdoc/driver/d3d11/d3d11_common.h index f83bb0bc0..9bfff32b5 100644 --- a/renderdoc/driver/d3d11/d3d11_common.h +++ b/renderdoc/driver/d3d11/d3d11_common.h @@ -282,12 +282,11 @@ public: #define USE_SCRATCH_SERIALISER() WriteSerialiser &ser = m_ScratchSerialiser; -#define SERIALISE_TIME_CALL(...) \ - m_ScratchSerialiser.ChunkMetadata().timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); \ - __VA_ARGS__; \ - m_ScratchSerialiser.ChunkMetadata().durationMicro = \ - RenderDoc::Inst().GetMicrosecondTimestamp() - \ - m_ScratchSerialiser.ChunkMetadata().timestampMicro; +#define SERIALISE_TIME_CALL(...) \ + m_ScratchSerialiser.ChunkMetadata().timestampMicro = Timing::GetTick(); \ + __VA_ARGS__; \ + m_ScratchSerialiser.ChunkMetadata().durationMicro = \ + Timing::GetTick() - m_ScratchSerialiser.ChunkMetadata().timestampMicro; // A handy macros to say "is the serialiser reading and we're doing replay-mode stuff?" // The reason we check both is that checking the first allows the compiler to eliminate the other diff --git a/renderdoc/driver/d3d12/d3d12_common.h b/renderdoc/driver/d3d12/d3d12_common.h index ad1640440..ae7743912 100644 --- a/renderdoc/driver/d3d12/d3d12_common.h +++ b/renderdoc/driver/d3d12/d3d12_common.h @@ -354,13 +354,12 @@ struct D3D12CommandSignature #define CACHE_THREAD_SERIALISER() WriteSerialiser &ser = GetThreadSerialiser(); -#define SERIALISE_TIME_CALL(...) \ - { \ - WriteSerialiser &ser = GetThreadSerialiser(); \ - ser.ChunkMetadata().timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); \ - __VA_ARGS__; \ - ser.ChunkMetadata().durationMicro = \ - RenderDoc::Inst().GetMicrosecondTimestamp() - ser.ChunkMetadata().timestampMicro; \ +#define SERIALISE_TIME_CALL(...) \ + { \ + WriteSerialiser &ser = GetThreadSerialiser(); \ + ser.ChunkMetadata().timestampMicro = Timing::GetTick(); \ + __VA_ARGS__; \ + ser.ChunkMetadata().durationMicro = Timing::GetTick() - ser.ChunkMetadata().timestampMicro; \ } // A handy macros to say "is the serialiser reading and we're doing replay-mode stuff?" diff --git a/renderdoc/driver/gl/gl_common.h b/renderdoc/driver/gl/gl_common.h index aa3cc2bfa..4d70353dc 100644 --- a/renderdoc/driver/gl/gl_common.h +++ b/renderdoc/driver/gl/gl_common.h @@ -452,12 +452,11 @@ T CheckConstParam(T t); #define USE_SCRATCH_SERIALISER() WriteSerialiser &ser = m_ScratchSerialiser; -#define SERIALISE_TIME_CALL(...) \ - m_ScratchSerialiser.ChunkMetadata().timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); \ - __VA_ARGS__; \ - m_ScratchSerialiser.ChunkMetadata().durationMicro = \ - RenderDoc::Inst().GetMicrosecondTimestamp() - \ - m_ScratchSerialiser.ChunkMetadata().timestampMicro; +#define SERIALISE_TIME_CALL(...) \ + m_ScratchSerialiser.ChunkMetadata().timestampMicro = Timing::GetTick(); \ + __VA_ARGS__; \ + m_ScratchSerialiser.ChunkMetadata().durationMicro = \ + Timing::GetTick() - m_ScratchSerialiser.ChunkMetadata().timestampMicro; // A handy macros to say "is the serialiser reading and we're doing replay-mode stuff?" // The reason we check both is that checking the first allows the compiler to eliminate the other diff --git a/renderdoc/driver/gl/wrappers/gl_debug_funcs.cpp b/renderdoc/driver/gl/wrappers/gl_debug_funcs.cpp index fcddab3b4..fc5333207 100644 --- a/renderdoc/driver/gl/wrappers/gl_debug_funcs.cpp +++ b/renderdoc/driver/gl/wrappers/gl_debug_funcs.cpp @@ -157,8 +157,7 @@ void WrappedOpenGL::glLabelObjectEXT(GLenum identifier, GLuint name, GLsizei len } else { - m_ScratchSerialiser.ChunkMetadata().timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); - m_ScratchSerialiser.ChunkMetadata().durationMicro = 0; + SERIALISE_TIME_CALL(); } if(IsCaptureMode(m_State)) @@ -188,8 +187,7 @@ void WrappedOpenGL::glObjectLabel(GLenum identifier, GLuint name, GLsizei length } else { - m_ScratchSerialiser.ChunkMetadata().timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); - m_ScratchSerialiser.ChunkMetadata().durationMicro = 0; + SERIALISE_TIME_CALL(); } if(IsCaptureMode(m_State)) @@ -219,8 +217,7 @@ void WrappedOpenGL::glObjectPtrLabel(const void *ptr, GLsizei length, const GLch } else { - m_ScratchSerialiser.ChunkMetadata().timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); - m_ScratchSerialiser.ChunkMetadata().durationMicro = 0; + SERIALISE_TIME_CALL(); } if(IsCaptureMode(m_State)) @@ -325,8 +322,7 @@ void WrappedOpenGL::glDebugMessageInsert(GLenum source, GLenum type, GLuint id, } else { - m_ScratchSerialiser.ChunkMetadata().timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); - m_ScratchSerialiser.ChunkMetadata().durationMicro = 0; + SERIALISE_TIME_CALL(); } HandleVRFrameMarkers(buf, length); @@ -470,8 +466,7 @@ void WrappedOpenGL::glPushDebugGroup(GLenum source, GLuint id, GLsizei length, c } else { - m_ScratchSerialiser.ChunkMetadata().timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); - m_ScratchSerialiser.ChunkMetadata().durationMicro = 0; + SERIALISE_TIME_CALL(); } if(IsActiveCapturing(m_State)) @@ -514,8 +509,7 @@ void WrappedOpenGL::glPopDebugGroup() } else { - m_ScratchSerialiser.ChunkMetadata().timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); - m_ScratchSerialiser.ChunkMetadata().durationMicro = 0; + SERIALISE_TIME_CALL(); } if(IsActiveCapturing(m_State)) diff --git a/renderdoc/driver/vulkan/vk_core.h b/renderdoc/driver/vulkan/vk_core.h index a3a47d2bc..cb8f9a0f1 100644 --- a/renderdoc/driver/vulkan/vk_core.h +++ b/renderdoc/driver/vulkan/vk_core.h @@ -186,13 +186,12 @@ struct VulkanDrawcallTreeNode } }; -#define SERIALISE_TIME_CALL(...) \ - { \ - WriteSerialiser &ser = GetThreadSerialiser(); \ - ser.ChunkMetadata().timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); \ - __VA_ARGS__; \ - ser.ChunkMetadata().durationMicro = \ - RenderDoc::Inst().GetMicrosecondTimestamp() - ser.ChunkMetadata().timestampMicro; \ +#define SERIALISE_TIME_CALL(...) \ + { \ + WriteSerialiser &ser = GetThreadSerialiser(); \ + ser.ChunkMetadata().timestampMicro = Timing::GetTick(); \ + __VA_ARGS__; \ + ser.ChunkMetadata().durationMicro = Timing::GetTick() - ser.ChunkMetadata().timestampMicro; \ } // must be at the start of any function that serialises diff --git a/renderdoc/serialise/rdcfile.cpp b/renderdoc/serialise/rdcfile.cpp index 6ca3c07be..2e206ad17 100644 --- a/renderdoc/serialise/rdcfile.cpp +++ b/renderdoc/serialise/rdcfile.cpp @@ -50,9 +50,9 @@ bool is_exr_file(FILE *f) /* ----------------------------- - File format for version 0x100: + File format for version 0x100 and up: - RDCHeader + FileHeader { uint64_t MAGIC_HEADER; @@ -60,13 +60,19 @@ bool is_exr_file(FILE *f) uint32_t headerLength; // length of this header, from the start of the file. Allows adding new // fields without breaking compatibilty char progVersion[16]; // string "v0.34" or similar with 0s after the string + } + BinaryThumbnail + { // thumbnail uint16_t thumbWidth; uint16_t thumbHeight; // thumbnail width and height. If 0x0, no thumbnail data uint32_t thumbLength; // number of bytes in thumbnail array below byte thumbData[ thumbLength ]; // JPG compressed thumbnail + } + CaptureMetaData + { // where was the capture created uint64_t machineIdent; @@ -76,6 +82,13 @@ bool is_exr_file(FILE *f) // implementation doesn't recognise the driver ID above } + if FileHeader.version >= 0x102 // new fields in 1.2 + CaptureTimeBase + { + uint64_t timeBase; // base tick count for capture timers + double timeFreq; // divisor for converting ticks to microseconds + } + 1 or more sections: Section @@ -183,6 +196,14 @@ struct CaptureMetaData char driverName[1] = {0}; }; +struct CaptureTimeBase +{ + // the base tick count for all timers in the capture + uint64_t timeBase = 0; + // the frequency conversion such that microseconds = ticks / frequency + double timeFreq = 1.0; +}; + struct BinarySectionHeader { // 0x0 @@ -320,7 +341,9 @@ void RDCFile::Init(StreamReader &reader) m_SerVer = header.version; - if(m_SerVer != SERIALISE_VERSION && m_SerVer != V1_0_VERSION) + // in v1.1 we changed chunk flags such that we could support 64-bit length. This is a backwards + // compatible change + if(m_SerVer != SERIALISE_VERSION && m_SerVer != V1_0_VERSION && m_SerVer != V1_1_VERSION) { if(header.version < V1_0_VERSION) { @@ -382,6 +405,23 @@ void RDCFile::Init(StreamReader &reader) RETURNERROR(ContainerError::FileIO, "I/O error reading driver name"); } + // this initialises to a default 'no conversion' timebase, with base of 0 and frequency of 1.0 + // which means old captures without a timebase won't see anything change + CaptureTimeBase timeBase; + + if(m_SerVer >= V1_2_VERSION) + { + reader.Read(&timeBase, sizeof(CaptureTimeBase)); + + if(reader.IsErrored()) + { + RETURNERROR(ContainerError::FileIO, "I/O error reading capture timebase"); + } + } + + // explicitly set this, so if we load an old capture with no timebase it gets reset back to a good + // default state even if we previously opened a capture with a timebase + RenderDoc::Inst().SetGlobalTimestampParameters(timeBase.timeBase, timeBase.timeFreq); m_Driver = meta.driverID; m_DriverName = driverName; @@ -707,7 +747,11 @@ void RDCFile::Create(const char *filename) meta.driverNameLength = uint8_t(m_DriverName.size() + 1); header.headerLength = sizeof(FileHeader) + offsetof(BinaryThumbnail, data) + thumbHeader.length + - offsetof(CaptureMetaData, driverName) + meta.driverNameLength; + offsetof(CaptureMetaData, driverName) + meta.driverNameLength + + sizeof(CaptureTimeBase); + + CaptureTimeBase timeBase; + RenderDoc::Inst().GetGlobalTimestampParameters(timeBase.timeBase, timeBase.timeFreq); { StreamWriter writer(m_File, Ownership::Nothing); @@ -722,6 +766,8 @@ void RDCFile::Create(const char *filename) writer.Write(m_DriverName.c_str(), meta.driverNameLength); + writer.Write(timeBase); + if(writer.IsErrored()) { RETURNERROR(ContainerError::FileIO, "Error writing file header"); diff --git a/renderdoc/serialise/rdcfile.h b/renderdoc/serialise/rdcfile.h index 3f6ca0d54..42ae24b69 100644 --- a/renderdoc/serialise/rdcfile.h +++ b/renderdoc/serialise/rdcfile.h @@ -60,12 +60,13 @@ public: // version number of overall file format or chunk organisation. If the contents/meaning/order of // chunks have changed this does not need to be bumped, there are version numbers within each // API that interprets the stream that can be bumped. - static const uint32_t SERIALISE_VERSION = 0x00000101; + static const uint32_t SERIALISE_VERSION = 0x00000102; // this must never be changed - files before this were in the v0.x series and didn't have embedded // version numbers static const uint32_t V1_0_VERSION = 0x00000100; static const uint32_t V1_1_VERSION = 0x00000101; + static const uint32_t V1_2_VERSION = 0x00000102; ~RDCFile(); diff --git a/renderdoc/serialise/serialiser.cpp b/renderdoc/serialise/serialiser.cpp index b51b19bab..dcbd1df8f 100644 --- a/renderdoc/serialise/serialiser.cpp +++ b/renderdoc/serialise/serialiser.cpp @@ -97,6 +97,8 @@ Serialiser::Serialiser(StreamReader *reader, Ownership if(rootStructuredObj) m_StructureStack.push_back(rootStructuredObj); + + RenderDoc::Inst().GetGlobalTimestampParameters(m_TimerBase, m_TimerFrequency); } template <> @@ -152,10 +154,20 @@ uint32_t Serialiser::BeginChunk(uint32_t, uint64_t) m_Read->Read(m_ChunkMetadata.threadID); if(c & ChunkDuration) + { m_Read->Read(m_ChunkMetadata.durationMicro); + if(m_TimerFrequency != 1.0) + m_ChunkMetadata.durationMicro = + int64_t(double(m_ChunkMetadata.durationMicro) / m_TimerFrequency); + } if(c & ChunkTimestamp) + { m_Read->Read(m_ChunkMetadata.timestampMicro); + if(m_TimerFrequency != 1.0 || m_TimerBase != 0) + m_ChunkMetadata.durationMicro = + int64_t(double(m_ChunkMetadata.timestampMicro - m_TimerBase) / m_TimerFrequency); + } if(c & Chunk64BitSize) { @@ -398,7 +410,7 @@ uint32_t Serialiser::BeginChunk(uint32_t chunkID, uint6 if(c & ChunkTimestamp) { if(m_ChunkMetadata.timestampMicro == 0) - m_ChunkMetadata.timestampMicro = RenderDoc::Inst().GetMicrosecondTimestamp(); + m_ChunkMetadata.timestampMicro = Timing::GetTick(); m_Write->Write(m_ChunkMetadata.timestampMicro); } diff --git a/renderdoc/serialise/serialiser.h b/renderdoc/serialise/serialiser.h index 4f98ec062..7455602ea 100644 --- a/renderdoc/serialise/serialiser.h +++ b/renderdoc/serialise/serialiser.h @@ -121,6 +121,11 @@ public: StreamReader *GetReader() { return m_Read; } uint32_t GetChunkMetadataRecording() { return m_ChunkFlags; } void SetChunkMetadataRecording(uint32_t flags); + void SetChunkTimestampBasis(uint64_t base, double freq) + { + m_TimerBase = base; + m_TimerFrequency = freq; + } // debug-only option to dump out (roughly) the data going through the serialiser as it happens void EnableDumping(FileIO::LogFileHandle *debugLog) { m_DebugDumpLog = debugLog; } @@ -1320,6 +1325,8 @@ private: uint32_t m_ChunkFlags = 0; SDChunkMetaData m_ChunkMetadata; + double m_TimerFrequency = 1.0; + uint64_t m_TimerBase = 0; // a database of strings read from the file, useful when serialised structures // expect a char* to return and point to static memory