[trace][intelpt] Support system-wide tracing [11] - Read warnings and perf conversion in the client

[wallace]

Summary

• Add logging for when the live state of the process is refreshed
• Move error handling of the live state refreshing to Trace from TraceIntelPT. This allows refreshing to fail either at the plug-in level or at the base class level. The error is cached and it can be gotten every time RefreshLiveProcessState is invoked.
• Allow DoRefreshLiveProcessState to handle plugin-specific parameters.
• Add some encapsulation to prevent TraceIntelPT from accessing variables belonging to Trace.

Test done via logging:

(lldb) b main
Breakpoint 1: where = a.out`main + 20 at main.cpp:27:20, address = 0x00000000004023d9
(lldb) r
Process 2359706 launched: '/home/wallace/a.out' (x86_64)
Process 2359706 stopped
* thread #1, name = 'a.out', stop reason = breakpoint 1.1
    frame #0: 0x00000000004023d9 a.out`main at main.cpp:27:20
   24   };
   25  
   26   int main() {
-> 27     std::vector<int> vvv;
   28     for (int i = 0; i < 100000; i++)
   29       vvv.push_back(i);
   30  
(lldb) process trace start                                                                                        (lldb) log enable lldb target -F(lldb) n
Process 2359706 stopped
* thread #1, name = 'a.out', stop reason = step over
    frame #0: 0x00000000004023e8 a.out`main at main.cpp:28:12
   25  
   26   int main() {
   27     std::vector<int> vvv;
-> 28     for (int i = 0; i < 100000; i++)
   29       vvv.push_back(i);
   30  
   31     std::deque<int> dq1 = {1, 2, 3};
(lldb) thread trace dump instructions -c 2 -t                                                                     
Trace.cpp:RefreshLiveProcessState                            Trace::RefreshLiveProcessState invoked
TraceIntelPT.cpp:DoRefreshLiveProcessState                   TraceIntelPT found tsc conversion information
thread #1: tid = 2359706
  a.out`std::vector<int, std::allocator<int>>::vector() + 26 at stl_vector.h:395:19
    54: [tsc=unavailable] 0x0000000000403a7c    retq

See the logging lines at the end of the dump. They indicate that refreshing happened and that perf conversion information was found. Logging is enabled with log enable lldb target

[jj10306]

lgtm

[stella.stamenova]

These changes (the set of [trace][intelpt] changes) broke the windows lldb bot. It's most likely this particular change, but it could be one of the others. Unfortunately, the bot had just been broken by https://reviews.llvm.org/D127882, so it didn't show the failure until that was reverted:

https://lab.llvm.org/buildbot/#/builders/83/builds/19994

[wallace]

yes, i'm trying to fix it now. Thanks!

Il giorno mer 15 giu 2022 alle ore 13:24 Stella Stamenova via Phabricator <
[e-mail]> ha scritto:

stella.stamenova added a comment.

These changes (the set of [trace][intelpt] changes) broke the windows lldb
bot. It's most likely this particular change, but it could be one of the
others. Unfortunately, the bot had just been broken by
https://reviews.llvm.org/D127882, so it didn't show the failure until
that was reverted:

https://lab.llvm.org/buildbot/#/builders/83/builds/19994

Repository:

rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION

https://reviews.llvm.org/D125943/new/

https://reviews.llvm.org/D125943

[stella.stamenova]

In D125943#3586910, @wallace wrote:

yes, i'm trying to fix it now. Thanks!

Thanks!

One more to add to the list:

FAILED: tools/lldb/source/Plugins/Process/Linux/CMakeFiles/lldbPluginProcessLinux.dir/IntelPTPerThreadProcessTrace.cpp.o 
/usr/bin/g++ -DHAVE_ROUND -D_DEBUG -D_GNU_SOURCE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -I/__w/1/b/llvm/Release/tools/lldb/source/Plugins/Process/Linux -I/__w/1/llvm-project/lldb/source/Plugins/Process/Linux -I/__w/1/llvm-project/lldb/include -I/__w/1/b/llvm/Release/tools/lldb/include -I/__w/1/b/llvm/Release/include -I/__w/1/llvm-project/llvm/include -I/__w/1/llvm-project/llvm/../clang/include -I/__w/1/b/llvm/Release/tools/lldb/../clang/include -I/__w/1/llvm-project/lldb/source -I/__w/1/b/llvm/Release/tools/lldb/source -fPIC -fno-semantic-interposition -fvisibility-inlines-hidden -Werror=date-time -Wall -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wno-missing-field-initializers -pedantic -Wno-long-long -Wimplicit-fallthrough -Wno-maybe-uninitialized -Wno-noexcept-type -Wdelete-non-virtual-dtor -Wno-comment -Wmisleading-indentation -fdiagnostics-color -ffunction-sections -fdata-sections -Wno-deprecated-declarations -Wno-unknown-pragmas -Wno-strict-aliasing -O3 -DNDEBUG  -fno-exceptions -UNDEBUG -std=c++14 -MD -MT tools/lldb/source/Plugins/Process/Linux/CMakeFiles/lldbPluginProcessLinux.dir/IntelPTPerThreadProcessTrace.cpp.o -MF tools/lldb/source/Plugins/Process/Linux/CMakeFiles/lldbPluginProcessLinux.dir/IntelPTPerThreadProcessTrace.cpp.o.d -o tools/lldb/source/Plugins/Process/Linux/CMakeFiles/lldbPluginProcessLinux.dir/IntelPTPerThreadProcessTrace.cpp.o -c /__w/1/llvm-project/lldb/source/Plugins/Process/Linux/IntelPTPerThreadProcessTrace.cpp
/__w/1/llvm-project/lldb/source/Plugins/Process/Linux/IntelPTPerThreadProcessTrace.cpp: In static member function 'static llvm::Expected<std::unique_ptr<lldb_private::process_linux::IntelPTProcessTrace> > lldb_private::process_linux::IntelPTPerThreadProcessTrace::Start(const lldb_private::TraceIntelPTStartRequest&, llvm::ArrayRef<long unsigned int>)':
/__w/1/llvm-project/lldb/source/Plugins/Process/Linux/IntelPTPerThreadProcessTrace.cpp:65:10: error: could not convert 'trace' from 'lldb_private::process_linux::IntelPTProcessTraceUP {aka std::unique_ptr<lldb_private::process_linux::IntelPTProcessTrace>}' to 'llvm::Expected<std::unique_ptr<lldb_private::process_linux::IntelPTProcessTrace> >'
   return trace;
          ^~~~~

This is on CentOS with gcc 7.3.1

[wallace]

@stella.stamenova, I've just tried that compile command with several versions of gcc, including g++ (GCC) 8.5.0 on CentOS and got no error Sadly I couldn't install 7.3.1. Could you try again in top of tree?

[stella.stamenova]

In D125943#3587778, @wallace wrote:

@stella.stamenova, I've just tried that compile command with several versions of gcc, including g++ (GCC) 8.5.0 on CentOS and got no error Sadly I couldn't install 7.3.1. Could you try again in top of tree?

Yes, it is still failing with 7.3.1 with the same error as before.

[wallace]

Hi @stella.stamenova, could you help fixing that one liner? I really have
no way to install gcc7 on my linux machine (I don't have permission to
install older gcc toolchains). I'm happy to chat with you on discord or
anywhere else to get this resolved.

Il giorno gio 16 giu 2022 alle ore 08:28 Stella Stamenova via Phabricator <
[e-mail]> ha scritto:

stella.stamenova added a comment.

In D125943#3587778 https://reviews.llvm.org/D125943#3587778, @wallace
wrote:

@stella.stamenova, I've just tried that compile command with several

versions of gcc, including g++ (GCC) 8.5.0 on CentOS and got no error Sadly
I couldn't install 7.3.1. Could you try again in top of tree?

Yes, it is still failing with 7.3.1 with the same error as before.

Repository:

rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION

https://reviews.llvm.org/D125943/new/

https://reviews.llvm.org/D125943

lldb/include/lldb/Target/Trace.h

public:
   ///     function.
   ///
   /// \return
   ///     An \a llvm::Error if the data couldn't be fetched, or the return value
   ///     of the callback, otherwise.
   llvm::Error OnThreadBinaryDataRead(lldb::tid_t tid, llvm::StringRef kind,
                                      OnBinaryDataReadCallback callback);
 
+  /// Get the current traced live process.
+  ///
+  /// \return
+  ///     The current traced live process. If it's not a live process,
+  ///     return \a nullptr.
+  Process *GetLiveProcess();
+
 protected:
   /// Implementation of \a OnThreadBinaryDataRead() for live threads.
   llvm::Error OnLiveThreadBinaryDataRead(lldb::tid_t tid, llvm::StringRef kind,
                                          OnBinaryDataReadCallback callback);
 
   /// Implementation of \a OnThreadBinaryDataRead() for post mortem threads.
   llvm::Error
   OnPostMortemThreadBinaryDataRead(lldb::tid_t tid, llvm::StringRef kind,
protected:
   llvm::Expected<std::string> GetLiveProcessState();
 
   /// Method to be overriden by the plug-in to refresh its own state.
   ///
   /// This is invoked by RefreshLiveProcessState when a new state is found.
   ///
   /// \param[in] state
   ///     The jLLDBTraceGetState response.
-  virtual void
-  DoRefreshLiveProcessState(llvm::Expected<TraceGetStateResponse> state) = 0;
+  ///
+  /// \param[in] json_response
+  ///     The original JSON response as a string. It might be useful to redecode
+  ///     it if it contains custom data for a specific trace plug-in.
+  ///
+  /// \return
+  ///     \b Error::success() if this operation succeedes, or an actual error
+  ///     otherwise.
+  virtual llvm::Error
+  DoRefreshLiveProcessState(TraceGetStateResponse state,
+                            llvm::StringRef json_response) = 0;
 
-  /// Method to be invoked by the plug-in to refresh the live process state.
+  /// Method to be invoked by the plug-in to refresh the live process state. It
+  /// will invoked DoRefreshLiveProcessState at some point, which should be
+  /// implemented by the plug-in for custom state handling.
+  ///
+  /// The result is cached through the same process stop. Even in the case of
+  /// errors, it caches the error.
   ///
-  /// The result is cached through the same process stop.
-  void RefreshLiveProcessState();
+  /// \return
+  ///   An error message if this operation failed, or \b nullptr otherwise.
+  const char *RefreshLiveProcessState();
 
+private:
   uint32_t m_stop_id = LLDB_INVALID_STOP_ID;
   /// Process traced by this object if doing live tracing. Otherwise it's null.
   Process *m_live_process = nullptr;
 
   /// These data kinds are returned by lldb-server when fetching the state of
   /// the tracing session. The size in bytes can be used later for fetching the
   /// data in batches.
   /// \{
 
   /// tid -> data kind -> size
   llvm::DenseMap<lldb::tid_t, std::unordered_map<std::string, size_t>>
       m_live_thread_data;
 
   /// data kind -> size
   std::unordered_map<std::string, size_t> m_live_process_data;
   /// \}
 
   /// Postmortem traces can specific additional data files, which are
   /// represented in this variable using a data kind identifier for each file.
   /// tid -> data kind -> file
   llvm::DenseMap<lldb::tid_t, std::unordered_map<std::string, FileSpec>>
       m_postmortem_thread_data;
+
+  llvm::Optional<std::string> m_live_refresh_error;
 };
 
 } // namespace lldb_private
 
 #endif // LLDB_TARGET_TRACE_H

lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.h

public:
   llvm::StringRef GetSchema() override;
 
   lldb::TraceCursorUP GetCursor(Thread &thread) override;
 
   void DumpTraceInfo(Thread &thread, Stream &s, bool verbose) override;
 
   llvm::Expected<size_t> GetRawTraceSize(Thread &thread);
 
-  void DoRefreshLiveProcessState(
-      llvm::Expected<TraceGetStateResponse> state) override;
+  llvm::Error DoRefreshLiveProcessState(TraceGetStateResponse state,
+                                        llvm::StringRef json_response) override;
 
   bool IsTraced(lldb::tid_t tid) override;
 
   const char *GetStartConfigurationHelp() override;
 
   /// Start tracing a live process.
   ///
   /// More information on the parameters below can be found in the
llvm::Error Start(llvm::ArrayRef<lldb::tid_t> tids,
                         StructuredData::ObjectSP()) override;
 
   /// See \a Trace::OnThreadBinaryDataRead().
   llvm::Error OnThreadBufferRead(lldb::tid_t tid,
                                  OnBinaryDataReadCallback callback);
 
   llvm::Expected<pt_cpu> GetCPUInfo();
 
-  /// Get the current traced live process.
-  ///
-  /// \return
-  ///     The current traced live process. If it's not a live process,
-  ///     return \a nullptr.
-  Process *GetLiveProcess();
 
   /// \return
   ///     The timer object for this trace.
   TaskTimer &GetTimer();
 
 private:
   friend class TraceIntelPTSessionFileParser;
 
private:
   ///     A \a DecodedThread shared pointer with the decoded instructions. Any
   ///     errors are embedded in the instruction list.
   DecodedThreadSP Decode(Thread &thread);
 
   /// It is provided by either a session file or a live process' "cpuInfo"
   /// binary data.
   llvm::Optional<pt_cpu> m_cpu_info;
   std::map<lldb::tid_t, std::unique_ptr<ThreadDecoder>> m_thread_decoders;
-  /// Error gotten after a failed live process update, if any.
-  llvm::Optional<std::string> m_live_refresh_error;
+  /// Helper variable used to track long running operations for telemetry.
   TaskTimer m_task_timer;
+  /// It is provided by either a session file or a live process to convert TSC
+  /// counters to and from nanos. It might not be available on all hosts.
+  llvm::Optional<LinuxPerfZeroTscConversion> m_tsc_conversion;
 };
 
 } // namespace trace_intel_pt
 } // namespace lldb_private
 
 #endif // LLDB_SOURCE_PLUGINS_TRACE_INTEL_PT_TRACEINTELPT_H

lldb/source/Plugins/Trace/intel-pt/TraceIntelPT.cpp

for (const ThreadPostMortemTraceSP &thread : traced_threads) {
     m_thread_decoders.emplace(thread->GetID(),
                               std::make_unique<ThreadDecoder>(thread, *this));
     SetPostMortemThreadDataFile(thread->GetID(), IntelPTDataKinds::kTraceBuffer,
                                 thread->GetTraceFile());
   }
 }
 
 DecodedThreadSP TraceIntelPT::Decode(Thread &thread) {
-  RefreshLiveProcessState();
-  if (m_live_refresh_error.hasValue())
+  if (const char *error = RefreshLiveProcessState())
     return std::make_shared<DecodedThread>(
         thread.shared_from_this(),
-        createStringError(inconvertibleErrorCode(), *m_live_refresh_error));
+        createStringError(inconvertibleErrorCode(), error));
 
   auto it = m_thread_decoders.find(thread.GetID());
   if (it == m_thread_decoders.end())
     return std::make_shared<DecodedThread>(
         thread.shared_from_this(),
         createStringError(inconvertibleErrorCode(), "thread not traced"));
   return it->second->Decode();
 }
if (!m_cpu_info) {
     if (llvm::Expected<pt_cpu> cpu_info = GetCPUInfoForLiveProcess())
       m_cpu_info = *cpu_info;
     else
       return cpu_info.takeError();
   }
   return *m_cpu_info;
 }
 
-Process *TraceIntelPT::GetLiveProcess() { return m_live_process; }
-
-void TraceIntelPT::DoRefreshLiveProcessState(
-    Expected<TraceGetStateResponse> state) {
+Error TraceIntelPT::DoRefreshLiveProcessState(TraceGetStateResponse state,
+                                              StringRef json_response) {
   m_thread_decoders.clear();
 
-  if (!state) {
-    m_live_refresh_error = toString(state.takeError());
-    return;
-  }
-
-  for (const TraceThreadState &thread_state : state->traced_threads) {
+  for (const TraceThreadState &thread_state : state.traced_threads) {
     ThreadSP thread_sp =
-        m_live_process->GetThreadList().FindThreadByID(thread_state.tid);
+        GetLiveProcess()->GetThreadList().FindThreadByID(thread_state.tid);
     m_thread_decoders.emplace(
         thread_state.tid, std::make_unique<ThreadDecoder>(thread_sp, *this));
   }
+
+  Expected<TraceIntelPTGetStateResponse> intelpt_state =
+      json::parse<TraceIntelPTGetStateResponse>(json_response,
+                                                "TraceIntelPTGetStateResponse");
+  if (!intelpt_state)
+    return intelpt_state.takeError();
+
+  m_tsc_conversion = intelpt_state->tsc_perf_zero_conversion;
+  if (m_tsc_conversion) {
+    Log *log = GetLog(LLDBLog::Target);
+    LLDB_LOG(log, "TraceIntelPT found TSC conversion information");
+  }
+  return Error::success();
 }
 
 bool TraceIntelPT::IsTraced(lldb::tid_t tid) {
   RefreshLiveProcessState();
   return m_thread_decoders.count(tid);
 }
 
 // The information here should match the description of the intel-pt section

lldb/source/Target/Trace.cpp

 
 #include "lldb/Core/Module.h"
 #include "lldb/Core/PluginManager.h"
 #include "lldb/Symbol/Function.h"
 #include "lldb/Target/ExecutionContext.h"
 #include "lldb/Target/Process.h"
 #include "lldb/Target/SectionLoadList.h"
 #include "lldb/Target/Thread.h"
+#include "lldb/Utility/LLDBLog.h"
 #include "lldb/Utility/Stream.h"
 
 using namespace lldb;
 using namespace lldb_private;
 using namespace llvm;
 
 // Helper structs used to extract the type of a trace session json without
 // having to parse the entire object.
return createStringError(
         inconvertibleErrorCode(),
         "Tracing data \"%s\" is not available for the process.", kind.data());
 
   TraceGetBinaryDataRequest request{GetPluginName().str(), kind.str(), None, 0,
                                     *size};
   return m_live_process->TraceGetBinaryData(request);
 }
 
-void Trace::RefreshLiveProcessState() {
+const char *Trace::RefreshLiveProcessState() {
   if (!m_live_process)
-    return;
+    return nullptr;
 
   uint32_t new_stop_id = m_live_process->GetStopID();
   if (new_stop_id == m_stop_id)
-    return;
+    return nullptr;
+
+  Log *log = GetLog(LLDBLog::Target);
+  LLDB_LOG(log, "Trace::RefreshLiveProcessState invoked");
 
   m_stop_id = new_stop_id;
   m_live_thread_data.clear();
+  m_live_refresh_error.reset();
+
+  auto HandleError = [&](Error &&err) -> const char * {
+    m_live_refresh_error = toString(std::move(err));
+    return m_live_refresh_error->c_str();
+  };
 
   Expected<std::string> json_string = GetLiveProcessState();
-  if (!json_string) {
-    DoRefreshLiveProcessState(json_string.takeError());
-    return;
-  }
+  if (!json_string)
+    return HandleError(json_string.takeError());
+
   Expected<TraceGetStateResponse> live_process_state =
       json::parse<TraceGetStateResponse>(*json_string, "TraceGetStateResponse");
-  if (!live_process_state) {
-    DoRefreshLiveProcessState(live_process_state.takeError());
-    return;
-  }
+  if (!live_process_state)
+    return HandleError(live_process_state.takeError());
+
+  for (std::string &warning : live_process_state->warnings)
+    LLDB_LOG(log, "Warning when fetching the trace state: {0}", warning);
 
   for (const TraceThreadState &thread_state :
        live_process_state->traced_threads) {
     for (const TraceBinaryData &item : thread_state.binary_data)
       m_live_thread_data[thread_state.tid][item.kind] = item.size;
   }
 
   for (const TraceBinaryData &item : live_process_state->process_binary_data)
     m_live_process_data[item.kind] = item.size;
 
-  DoRefreshLiveProcessState(std::move(live_process_state));
+  if (Error err = DoRefreshLiveProcessState(std::move(*live_process_state),
+                                            *json_string))
+    return HandleError(std::move(err));
+
+  return nullptr;
 }
 
+Process *Trace::GetLiveProcess() { return m_live_process; }
+
 uint32_t Trace::GetStopID() {
   RefreshLiveProcessState();
   return m_stop_id;
 }
 
 llvm::Expected<FileSpec>
 Trace::GetPostMortemThreadDataFile(lldb::tid_t tid, llvm::StringRef kind) {
   auto NotFoundError = [&]() {