Add a more succinct logging syntax

[labath]

Summary

Is there anything left I need to do here?

[zturner]

A couple comments:

1. If we're going to use formatv (yay!) then let's standardize. No point mising formatv and streaming, especially when the former will almost always be less verbose.

2. One of the concerns that came up last time was that of evaluating the arguments to the logging functions even in the case where it didn't get logged, because sometimes just calling the function to evaluate the parameter can be expensive. To get around that you could pass the arguments directly to the macro instead of streaming them, and the macro could wrap everything in a lambda.

Combining #1 and #2 above, maybe you end up with something like this (not tested, probably needs some tweaking to work):

#define LLDB_LOG(...) LLDB_LOG_([]() { return llvm::formatv(__VA_ARGS__); }

LLDB_LOG("pid = {0}: tracking new thread tid {1}", GetID(), tid);

[labath]

In D27459#614549, @zturner wrote:

A couple comments:

1. If we're going to use formatv (yay!) then let's standardize. No point mising formatv and streaming, especially when the former will almost always be less verbose.

In this change, I deliberately tried to mix styles, to show different ways of doing things. I also wanted to avoid prescribing the right API to use, as I've found llvm::formatv to be longer in the simple cases. However, hiding it in a macro is a good idea, and would remove that problem.

2. One of the concerns that came up last time was that of evaluating the arguments to the logging functions even in the case where it didn't get logged, because sometimes just calling the function to evaluate the parameter can be expensive. To get around that you could pass the arguments directly to the macro instead of streaming them, and the macro could wrap everything in a lambda.

The macro expands to something like if (!log) /*do nothing*/; else log << whatever, so the streaming part only gets executed if logging is actually enabled. That said, I like the API you propose as well (and it could probably use something similar under the hood, to avoid messing around with lambdas).

[clayborg]

Part of the reason I like the current "if (log) log->Printf()" is that it doesn't cost you much if logging isn't enabled. So if you have a log line like:

if (log)
  log->Printf("%s %s %s", myStringRef1.str().c_str(), myStringRef2.str().c_str(), myStringRef3.str().c_str());

And switch over to using:

LLDB_LOG() << myStringRef1 << " " << myStringRef2 << " " << myStringRef2;

You end up doing some work with all of the types regardless of wether the logging is enabled. We tend to do pretty heavy logging in places and I really don't want performance impacted (the expression parser emits a full novel worth of information when logging is enabled), nor would I want people to log less because they are worried about affecting performance.

So any solution should have very minimal cost if logging isn't enabled. We also do log channels, so any design will need to include the ability to log to a channel, any channel, or only if all channels are enabled.

The other thing I don't like about streams is they are harder to read over a printf style log string. I wrote all of dwarfdump and used the full power off C++ streams and I regret doing this as all of the code is really hard to read. I also didn't like the fact that streams maintain state and can affect things down the line. If we adopt LLVM style streams I believe they don't suffer from the C++ streams having state issue. But with C++ you can do this:

std::cout << std::dec << 12;
std::cout << 24;

And then you add some code in the middle:

std::cout << std::dec << 12;
std::cout << std::hex << 0x1234;
std::cout << 24;

Now your "24" comes out as hex instead of decimal. This means you have to start always specifying your state:

std::cout << std::dec << 12;
std::cout << std::hex << 0x1234;
std::cout << std::dec << 24;

So my main objection is the cost of logging when it isn't enable with this approach. I am going to assume we won't use any state in streams if we do ever make something like this. I would still also like the ability to use Printf in the new logs if we do come up with a solution.

How can be solve the performance problem with this approach?

[clayborg]

Does llvm::formatv allow you to specify the base of integers, or just where they go? Can you give it width, number base, leading characters and other things like a lot of what printf does?

[clayborg]

I am fine with us changing logging, just want to make sure it works well. Ideally it would include:

• almost zero cost when logging disabled. No arguments should be passed to any functions and then determine that logging is disabled, it should check if logging is enabled and not do any of the work if it isn't.
• no state in streams so adding logging before other logging can't affect future output
• the ability to some form if format strings (printf for formatv style strings) so not everything has to be done with streams and control codes that are sent into the stream to change from decimal to hex etc
• I would rather avoid macros if possible, though we might have to use them to get the performance

[zturner]

In D27459#614670, @clayborg wrote:

Part of the reason I like the current "if (log) log->Printf()" is that it doesn't cost you much if logging isn't enabled. So if you have a log line like:

if (log)
  log->Printf("%s %s %s", myStringRef1.str().c_str(), myStringRef2.str().c_str(), myStringRef3.str().c_str());

And switch over to using:

LLDB_LOG() << myStringRef1 << " " << myStringRef2 << " " << myStringRef2;

You end up doing some work with all of the types regardless of wether the logging is enabled. We tend to do pretty heavy logging in places and I really don't want performance impacted (the expression parser emits a full novel worth of information when logging is enabled), nor would I want people to log less because they are worried about affecting performance.

So any solution should have very minimal cost if logging isn't enabled. We also do log channels, so any design will need to include the ability to log to a channel, any channel, or only if all channels are enabled.

The other thing I don't like about streams is they are harder to read over a printf style log string. I wrote all of dwarfdump and used the full power off C++ streams and I regret doing this as all of the code is really hard to read. I also didn't like the fact that streams maintain state and can affect things down the line. If we adopt LLVM style streams I believe they don't suffer from the C++ streams having state issue. But with C++ you can do this:

Take a look at llvm::formatv. I wrote this in LLVM specifically to be the best of both worlds. You get all the flexibility and conciseness of printf with all the type safety of streams. Example:

// Printf style
log->Printf("%d %s %z", 12, "test", (size_t)7);

// Stream style
*log << 12 << "test" << (size_t)7;

// formatv style
*log << llvm::formatv("{0} {1} {2}", 12, "test", (size_t)7);

// alternative formatv sytle
log->Formatv("{0} {1} {2}", 12, "test", (size_t)7);

As you can see, you don't have to specify the type. All the ugliness about PRIx64, compiler inconsistencies, platform-dependent sizes, etc all disappear because it deduces the type. And it's even better than this, because you can write custom formatters for your own types. For examples, LLDB has a class called AddressRange. With printf you would have to write this log->Printf("%llu - %llu", range.first(), range.second())', but with formatv` you can write this: log->Formatv("{0}", range); as long as it can find a formatter somewhere. And formatters can define arbitrary style options too, so you could write something like log->Formatv("{0:abc}", range); and this string "abc" would get passed to the formatter's format function. This is useful when a type is often formatted different ways (precision, optional fields, etc).

I strongly recommend moving to this for all printf style formatting moving forward.

[zturner]

In D27459#614672, @clayborg wrote:

Does llvm::formatv allow you to specify the base of integers, or just where they go? Can you give it width, number base, leading characters and other things like a lot of what printf does?

You can specify hex and decimal. No other bases, although that could be added. To the other questions, yes. Here are some examples:

std::string S = formatv("{0}", 7);   // S = "7"
S = formatv("{0,-3}", 7);   // S = "7  "  (-3 indicates left align inside a field of width 3)
S = formatv("{0,=3}", 7);  // S = " 7 "  (=3 indicates center align inside a field of width 3)
S = formatv("{0,=10; x}, 23);  // S = "   0x17   "  (=10 indicates center align inside a field of width 10, x indicates hex.   , is the alignment marker ; is the style marker
S = formatv("{0;P}", 0.12345);  // S = "12.35%"  (P indicates to format as a percentage, only valid for floating point types.  Default precision is 2
S = formatv("{0;3P}", 0.12345);  // S = "12.345%"  (P indicates to format as a percentage, only valid for floating point types.  Explicitly specify precision of 3.

There are lots of other things you can do, and since I wrote / designed it, I'm happy to add additional features that you or others request.

[jingham]

I not infrequently have some non-trivial code in the "if (log)" block that gathers the information that I am then going to print, or loops over entities printing them. Putting more complex code like that inside a macro looks awful and is hard to debug. I don't think that argues for not using the macros in the case where you are logging a simple string, but it does argue for keeping the old way available.

Also, some extant log messages don't have file and function because they are making structured readable output and the function noise is just that, and makes the logs harder to read. It's worse when constructing logs that span functions because you would have to work way too hard to line things up nicely. If we're going to keep the old log mechanism around, that's okay, you can just continue to use that for these purposes. Otherwise, you might want have decorated and non-decorated variants.

[labath]

This discussion has diverged across lldb-dev and lldb-commits. I think we should move it to one place. I propose lldb-dev, as that seems a better place for high-level discussions.

[labath]

Update the example to the formatv-based API

[clayborg]

Seems weird that we are a C++ codebase and we fall back to C macros. We currently need the macro only for file + line and to also not have to worry about doing "if (log) log->". I am not a big fan of macros, but I am open to it if everyone else wants it.

include/lldb/Core/Log.h

218–219 ↗

(On Diff #80744)

This is hard coding in the file + line all the time. I would like this to be an option. We also need to be able to optionally enable the pid/tid, thread name, stack backtrace and all the other options that are currently supported by "log enable". Seems like we need a log function that exists in Log.cpp to take a log mutex, add the extra log prefix stuff (file + line, pid/tid, thread name, timestamp, delta since last log time, stack etc) and then call the llvm::formatv() one or more times and then release the mutex.

include/lldb/Host/FileSpec.h

675–677 ↗

(On Diff #80744)

For a good example of what objects can do to help sell this proposal we should handle different values for the Options string. Maybe this to support the following:

Options is empty -> print out full path
Options == "filename" -> print out file name only with extension
Options == "basename" -> print out file name only without extension
Options == "directory" -> print out file directory only
Options == "extension" -> print out file extension only
Options == "volume" -> print out file volume only which will probably only work on windows paths currently
Options == "fullname" -> print out volume + directory + filename, same as default empty string

Then we can format like:

FileSpec file("/tmp/foo.txt");
llvm::formatv("{0; filename}", file);

[jasonmolenda]

A couple of thoughts / two cents.

I don't mind the current if (log) { ... } style of logging, even with the PRIx64's and having to do filepath.GetPath().c_str() and all that. I like being able to do extra work in a if (log) block of code -- create a SymbolContext for something or whatever, and as I'm debugging that section of code I like to be able to put a breakpoint there and look more closely. If this is all in a preprocessor macro, a breakpoint is going to stop me on the if() and then I'm trying to step through a macro? And if my computation is down in a lambda I need to figure out how to put a breakpoint in that or step into that somehow to look at the values being computed. How do I create a SymbolContext my_symctx(...); and then include that in what I log if I have to do all of this in the formatv arguments?

I'm not thrilled with the formatv reinvention of format specification. The printf formatters are a bizarre little invention, but it's a bizarre invention that we've all worked with for decades and everyone who works in C knows well. The formatv format specification may be superior, but I don't want to see innovation here, I want clarity with the linga franca that every C programmer knows. I think the barrier to adopting something non-standard is very high.

The formatv format specification string seems to explicitly mention the ordering of the arguments, like llvm::formatv("{0} {1} {2}", first, second, third). I'm guessing this allows you to print the arguments in different order than they appear? Like llvm::formatv("{0} {2} {2} {1}", first, second, third)? What's the benefit of this vrs. the uncertainty of which arguments are used in different parts of the string (short of counting them out by hand)? If I have a formatv format specification like "{0} {1} {2} {3} {4}" and I want to insert an argument between 2 and 3, I need to renumber 3 and 4 now? Or do I do "{0} {1} {2} {5} {3} {4}" and throw my argument on to the end?

Simply *ability* to put the arguments in any order is my concern. Of course I'm never going to do it, but I'm going to have to work on code where other people have done it.

I don't personally want to see the file / function / line numbers in my logging. It's fine if that's an option that other people can enable if they want it. There's going to be a growth in the size of our text for the constant strings for every log point having its filename and function, but it will probably not be significant (maybe the strings can be coalesced, I wouldn't bet one way or the other.)

If formatv could take something a LOT closer to printf, I'd be better with it. Something like the python string formatters would be a real improvement - just %d for base 10 numbers, not having to worry about the size of the argument in the format string, for instance, and would still be readable & understandable by any C programmer out there.

If we're going to start using this alternate logging scheme, eventually there will be a push to use it everywhere, or someone will go through all the other classes in the code base and switch it out without consultation. We need to all sign on to this idea before it goes into the code base at all.

[labath]

I'll respond to your comments on the lldb-dev thread.

include/lldb/Core/Log.h

218–219 ↗

(On Diff #80744)

I am planning to make the source information optional. This diff is mainly here to demonstrate the target syntax from the users point of view. The changes are made here are not to be taken as examples of good coding practices - it is just the minimal set of changes I needed to do to make things work. When we agree on the final syntax, I'll implement this more nicely.

[labath]

• Replace the hacky proof-of-concept implementation with something more production-ready
• Add a option to control adding of source information (defaulting to on)
• Add some unit tests
• Add an example of how would ProcessWindowsLog look like with this syntax

[clayborg]

Looks fine except I would rather not have file + line on by default.

source/Commands/CommandObjectLog.cpp

51–52 ↗

(On Diff #83967)

This shouldn't be on by default. Maybe it should be renamed to "file-line".

103 ↗

(On Diff #83967)

Don't default this to on.

135–136 ↗

(On Diff #83967)

Reverse

[labath]

• Several people expressed wishes to have this off by default, so I have done that.
• Renamed the log option to --file-function (Note I am deliberately not printing the line numbers -- they tend to change all the time and it's more consistent with what the code is currently doing)
• I am planning to submit the core changes only, the refactors are here just for illustration, and I'll handle them separately.

[labath]

Final version. No real changes, just removed usage changes in NativeProcessLinux
I will put in as sepearate patches.

[clayborg]

Looks good.

[dancol]

source/Core/Log.cpp

78 ↗

(On Diff #84690)

I usually implement printf-into-std::string by using vsnprintf to figure out how many characters we generate, using std::string::resize to create a buffer of that many characters (unfortunately, zero-filling them), then vsnprintf directly into that buffer. This way, you only need one allocation.

The currant approach involves at least three allocations: first, the string generated by vasprintf. Second, the internal stringstream buffer. Third, the copy of the buffer that std::stringstream::str generates.

It's more expensive that it needs to be.

[zturner]

source/Core/Log.cpp

78 ↗

(On Diff #84690)

To be fair, we should really be deleting these methods long term, and using formatv. This way you often end up with 0 allocations (for short messages), and on top of that, only one underlying format call (as opposed to wasting time calling vasprintf twice here).

[labath]

source/Core/Log.cpp

78 ↗

(On Diff #84690)

The currant approach involves at least three allocations: first, the string generated by vasprintf. Second, the internal stringstream buffer. Third, the copy of the buffer that std::stringstream::str generates.

str() returns a reference to the underlying buffer (this is an llvm stream, not std::stringstream), so there is no copy there. Since this is not really performance critical, I'd prefer to keep the code simpler (plus, I think the extra vsnprintf call balances the extra malloc, roughly speaking).

And, same as Zachary, I hope this code will go away eventually.

lldb/trunk/include/lldb/Core/Log.h

 //===-- Log.h ---------------------------------------------------*- C++ -*-===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #ifndef liblldb_Log_h_
 #define liblldb_Log_h_
 
-// C Includes
-#include <signal.h>
-#include <stdarg.h>
-#include <stdint.h>
-#include <stdio.h>
-
-// C++ Includes
-// Other libraries and framework includes
 // Project includes
 #include "lldb/Core/ConstString.h"
 #include "lldb/Core/Flags.h"
 #include "lldb/Core/Logging.h"
 #include "lldb/Core/PluginInterface.h"
 #include "lldb/lldb-private.h"
 
+// Other libraries and framework includes
 #include "llvm/Support/FormatVariadic.h"
+// C++ Includes
+#include <cstdarg>
+#include <cstdint>
+// C Includes
 
 //----------------------------------------------------------------------
 // Logging Options
 //----------------------------------------------------------------------
 #define LLDB_LOG_OPTION_THREADSAFE (1u << 0)
 #define LLDB_LOG_OPTION_VERBOSE (1u << 1)
 #define LLDB_LOG_OPTION_DEBUG (1u << 2)
 #define LLDB_LOG_OPTION_PREPEND_SEQUENCE (1u << 3)
 #define LLDB_LOG_OPTION_PREPEND_TIMESTAMP (1u << 4)
 #define LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD (1u << 5)
 #define LLDB_LOG_OPTION_PREPEND_THREAD_NAME (1U << 6)
 #define LLDB_LOG_OPTION_BACKTRACE (1U << 7)
 #define LLDB_LOG_OPTION_APPEND (1U << 8)
+#define LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION (1U << 9)
 
 //----------------------------------------------------------------------
 // Logging Functions
 //----------------------------------------------------------------------
 namespace lldb_private {
 
 class Log final {
 public:
public:
 
   Log(const lldb::StreamSP &stream_sp);
 
   ~Log();
 
   void PutCString(const char *cstr);
   void PutString(llvm::StringRef str);
 
-  template <typename... Args> void Format(const char *fmt, Args &&... args) {
-    PutString(llvm::formatv(fmt, std::forward<Args>(args)...).str());
+  template <typename... Args>
+  void Format(llvm::StringRef file, llvm::StringRef function,
+              const char *format, Args &&... args) {
+    Format(file, function, llvm::formatv(format, std::forward<Args>(args)...));
   }
 
   // CLEANUP: Add llvm::raw_ostream &Stream() function.
   void Printf(const char *format, ...) __attribute__((format(printf, 2, 3)));
 
   void VAPrintf(const char *format, va_list args);
 
   void LogIf(uint32_t mask, const char *fmt, ...)
protected:
   // Member variables
   //------------------------------------------------------------------
   lldb::StreamSP m_stream_sp;
   Flags m_options;
   Flags m_mask_bits;
 
 private:
   DISALLOW_COPY_AND_ASSIGN(Log);
+
+  void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
+                   llvm::StringRef function);
+  void WriteMessage(const std::string &message);
+
+  void Format(llvm::StringRef file, llvm::StringRef function,
+              const llvm::formatv_object_base &payload);
 };
 
 class LogChannel : public PluginInterface {
 public:
   LogChannel();
 
   ~LogChannel() override;
 
protected:
   std::unique_ptr<Log> m_log_ap;
 
 private:
   DISALLOW_COPY_AND_ASSIGN(LogChannel);
 };
 
 } // namespace lldb_private
 
+#define LLDB_LOG(log, ...)                                                     \
+  do {                                                                         \
+    ::lldb_private::Log *log_private = (log);                                  \
+    if (log_private)                                                           \
+      log_private->Format(__FILE__, __FUNCTION__, __VA_ARGS__);                \
+  } while (0)
+
 #endif // liblldb_Log_h_

lldb/trunk/source/Commands/CommandObjectLog.cpp

static OptionDefinition g_log_options[] = {
   { LLDB_OPT_SET_1, false, "verbose",    'v', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Enable verbose logging." },
   { LLDB_OPT_SET_1, false, "debug",      'g', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Enable debug logging." },
   { LLDB_OPT_SET_1, false, "sequence",   's', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Prepend all log lines with an increasing integer sequence id." },
   { LLDB_OPT_SET_1, false, "timestamp",  'T', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Prepend all log lines with a timestamp." },
   { LLDB_OPT_SET_1, false, "pid-tid",    'p', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Prepend all log lines with the process and thread ID that generates the log line." },
   { LLDB_OPT_SET_1, false, "thread-name",'n', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Prepend all log lines with the thread name for the thread that generates the log line." },
   { LLDB_OPT_SET_1, false, "stack",      'S', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Append a stack backtrace to each log line." },
   { LLDB_OPT_SET_1, false, "append",     'a', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Append to the log file instead of overwriting." },
+  { LLDB_OPT_SET_1, false, "file-function",'F',OptionParser::eNoArgument,      nullptr, nullptr, 0, eArgTypeNone,     "Prepend the names of files and function that generate the logs." },
     // clang-format on
 };
 
 class CommandObjectLogEnable : public CommandObjectParsed {
 public:
   //------------------------------------------------------------------
   // Constructors and Destructors
   //------------------------------------------------------------------
Error SetOptionValue(uint32_t option_idx, llvm::StringRef option_arg,
         log_options |= LLDB_LOG_OPTION_PREPEND_THREAD_NAME;
         break;
       case 'S':
         log_options |= LLDB_LOG_OPTION_BACKTRACE;
         break;
       case 'a':
         log_options |= LLDB_LOG_OPTION_APPEND;
         break;
+      case 'F':
+        log_options |= LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION;
       default:
         error.SetErrorStringWithFormat("unrecognized option '%c'",
                                        short_option);
         break;
       }
 
       return error;
     }

lldb/trunk/source/Core/Log.cpp

 #include "lldb/Host/Host.h"
 #include "lldb/Host/ThisThread.h"
 #include "lldb/Interpreter/Args.h"
 #include "lldb/Utility/NameMatches.h"
 
 // Other libraries and framework includes
 #include "llvm/ADT/SmallString.h"
 #include "llvm/Support/Chrono.h"
+#include "llvm/Support/Path.h"
 #include "llvm/Support/Signals.h"
 #include "llvm/Support/raw_ostream.h"
 
 // C Includes
 // C++ Includes
 #include <cstdarg>
 #include <cstdio>
 #include <cstdlib>

 }
 
 //----------------------------------------------------------------------
 // All logging eventually boils down to this function call. If we have
 // a callback registered, then we call the logging callback. If we have
 // a valid file handle, we also log to the file.
 //----------------------------------------------------------------------
 void Log::VAPrintf(const char *format, va_list args) {
-  // Make a copy of our stream shared pointer in case someone disables our
-  // log while we are logging and releases the stream
-  StreamSP stream_sp(m_stream_sp);
-  if (stream_sp) {
-    static uint32_t g_sequence_id = 0;
-    StreamString header;
-
-    // Add a sequence ID if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
-      header.Printf("%u ", ++g_sequence_id);
-
-    // Timestamp if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
-      auto now = std::chrono::duration<double>(
-          std::chrono::system_clock::now().time_since_epoch());
-      header.Printf("%.9f ", now.count());
-    }
-
-    // Add the process and thread if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
-      header.Printf("[%4.4x/%4.4" PRIx64 "]: ", getpid(),
-                    Host::GetCurrentThreadID());
-
-    // Add the thread name if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
-      llvm::SmallString<32> thread_name;
-      ThisThread::GetName(thread_name);
-      if (!thread_name.empty())
-        header.Printf("%s ", thread_name.c_str());
-    }
+  std::string message_string;
+  llvm::raw_string_ostream message(message_string);
+  WriteHeader(message, "", "");
+
+  char *text;
+  vasprintf(&text, format, args);
+  message << text;
+  free(text);
 
-    header.PrintfVarArg(format, args);
-    header.PutCString("\n");
+  message << "\n";
 
-    if (m_options.Test(LLDB_LOG_OPTION_BACKTRACE)) {
-      std::string back_trace;
-      llvm::raw_string_ostream stream(back_trace);
-      llvm::sys::PrintStackTrace(stream);
-      stream.flush();
-      header.PutCString(back_trace);
-    }
-
-    if (m_options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
-      static std::recursive_mutex g_LogThreadedMutex;
-      std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
-      stream_sp->PutCString(header.GetString());
-      stream_sp->Flush();
-    } else {
-      stream_sp->PutCString(header.GetString());
-      stream_sp->Flush();
-    }
-  }
+  WriteMessage(message.str());
 }
 
 //----------------------------------------------------------------------
 // Print debug strings if and only if the global debug option is set to
 // a non-zero value.
 //----------------------------------------------------------------------
 void Log::Debug(const char *format, ...) {
   if (!GetOptions().Test(LLDB_LOG_OPTION_DEBUG))

 //------------------------------------------------------------------
 // Returns true if the debug flag bit is set in this stream.
 //------------------------------------------------------------------
 bool Log::GetDebug() const {
   // TODO: remove and clean up callers
   return false;
 }
 
+void Log::WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
+                      llvm::StringRef function) {
+  static uint32_t g_sequence_id = 0;
+  // Add a sequence ID if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
+    OS << ++g_sequence_id << " ";
+
+  // Timestamp if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
+    auto now = std::chrono::duration<double>(
+        std::chrono::system_clock::now().time_since_epoch());
+    OS << llvm::formatv("{0:f9} ", now.count());
+  }
+
+  // Add the process and thread if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
+    OS << llvm::formatv("[{0,0+4}/{1,0+4}] ", getpid(),
+                        Host::GetCurrentThreadID());
+
+  // Add the thread name if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
+    llvm::SmallString<32> thread_name;
+    ThisThread::GetName(thread_name);
+    if (!thread_name.empty())
+      OS << thread_name;
+  }
+
+  if (m_options.Test(LLDB_LOG_OPTION_BACKTRACE))
+    llvm::sys::PrintStackTrace(OS);
+
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION) &&
+      (!file.empty() || !function.empty())) {
+    file = llvm::sys::path::filename(file).take_front(40);
+    function = function.take_front(40);
+    OS << llvm::formatv("{0,-60:60} ", (file + ":" + function).str());
+  }
+}
+
+void Log::WriteMessage(const std::string &message) {
+  // Make a copy of our stream shared pointer in case someone disables our
+  // log while we are logging and releases the stream
+  StreamSP stream_sp(m_stream_sp);
+  if (!stream_sp)
+    return;
+
+  if (m_options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
+    static std::recursive_mutex g_LogThreadedMutex;
+    std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
+    stream_sp->PutCString(message.c_str());
+    stream_sp->Flush();
+  } else {
+    stream_sp->PutCString(message.c_str());
+    stream_sp->Flush();
+  }
+}
+
+void Log::Format(llvm::StringRef file, llvm::StringRef function,
+                 const llvm::formatv_object_base &payload) {
+  std::string message_string;
+  llvm::raw_string_ostream message(message_string);
+  WriteHeader(message, file, function);
+  message << payload << "\n";
+  WriteMessage(message.str());
+}
+
 LogChannelSP LogChannel::FindPlugin(const char *plugin_name) {
   LogChannelSP log_channel_sp;
   LogChannelMap &channel_map = GetChannelMap();
   ConstString log_channel_name(plugin_name);
   LogChannelMapIter pos = channel_map.find(log_channel_name);
   if (pos == channel_map.end()) {
     ConstString const_plugin_name(plugin_name);
     LogChannelCreateInstance create_callback =

lldb/trunk/source/Plugins/ExpressionParser/Clang/IRForTarget.cpp

  case 2:
    encoding_flags = 0x0100; /* 0x0100 is kCFStringEncodingUTF16 */
    break;
  case 4:
    encoding_flags = 0x0c000100; /* 0x0c000100 is kCFStringEncodingUTF32 */
    break;
  default:
    encoding_flags = 0x0600; /* fall back to 0x0600, kCFStringEncodingASCII */
-   if (log) {
-     log->Format("Encountered an Objective-C constant string with unusual "
+   LLDB_LOG(log, "Encountered an Objective-C constant string with unusual "
                  "element size {0}",
-                 string_array->getElementByteSize());
-   }
- }
  Constant *encoding_arg = ConstantInt::get(i32_ty, encoding_flags, false);
  Constant *isExternal_arg =
      ConstantInt::get(i8_ty, 0x0, false); /* 0x0 is false */
 
  Value *argument_array[5];
 
  argument_array[0] = alloc_arg;
  argument_array[1] = bytes_arg;

lldb/trunk/tools/lldb-server/lldb-gdbserver.cpp

#endif
     }
   }
 
   if (show_usage || option_error) {
     display_usage(progname, subcommand);
     exit(option_error);
   }
 
-  if (!LLDBServerUtilities::SetupLogging(log_file, log_channels,
-                                         LLDB_LOG_OPTION_PREPEND_TIMESTAMP))
+  if (!LLDBServerUtilities::SetupLogging(
+          log_file, log_channels,
+          LLDB_LOG_OPTION_PREPEND_TIMESTAMP |
+              LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION))
     return -1;
 
   Log *log(lldb_private::GetLogIfAnyCategoriesSet(GDBR_LOG_VERBOSE));
   if (log) {
     log->Printf("lldb-server launch");
     for (int i = 0; i < argc; i++) {
       log->Printf("argv[%i] = '%s'", i, argv[i]);
     }

lldb/trunk/unittests/Core/CMakeLists.txt

 add_lldb_unittest(LLDBCoreTests
   ArchSpecTest.cpp
   BroadcasterTest.cpp
   DataExtractorTest.cpp
   ErrorTest.cpp
   ListenerTest.cpp
+  LogTest.cpp
   ScalarTest.cpp
   StructuredDataTest.cpp
   TimerTest.cpp
   )

lldb/trunk/unittests/Core/LogTest.cpp

+//===-- LogTest.cpp ---------------------------------------------*- C++ -*-===//
+//
+//                     The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+
+#include "lldb/Core/Log.h"
+#include "lldb/Core/StreamString.h"
+#include "lldb/Host/Host.h"
+#include "gtest/gtest.h"
+
+using namespace lldb;
+using namespace lldb_private;
+
+static std::string GetLogString(uint32_t log_options, const char *format,
+                                int arg) {
+  std::shared_ptr<StreamString> stream_sp(new StreamString());
+  Log log_(stream_sp);
+  log_.GetOptions().Reset(log_options);
+  Log *log = &log_;
+  LLDB_LOG(log, format, arg);
+  return stream_sp->GetString();
+}
+
+TEST(LogTest, LLDB_LOG_nullptr) {
+  Log *log = nullptr;
+  LLDB_LOG(log, "{0}", 0); // Shouldn't crash
+}
+
+TEST(LogTest, log_options) {
+  EXPECT_EQ("Hello World 47\n", GetLogString(0, "Hello World {0}", 47));
+  EXPECT_EQ("Hello World 47\n",
+            GetLogString(LLDB_LOG_OPTION_THREADSAFE, "Hello World {0}", 47));
+
+  {
+    std::string msg =
+        GetLogString(LLDB_LOG_OPTION_PREPEND_SEQUENCE, "Hello World {0}", 47);
+    int seq_no;
+    EXPECT_EQ(1, sscanf(msg.c_str(), "%d Hello World 47", &seq_no));
+  }
+
+  EXPECT_EQ(
+      "LogTest.cpp:GetLogString                                     Hello "
+      "World 47\n",
+      GetLogString(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION, "Hello World {0}", 47));
+
+  EXPECT_EQ(llvm::formatv("[{0}/{1}] Hello World 47\n",
+                          Host::GetCurrentProcessID(),
+                          Host::GetCurrentThreadID())
+                .str(),
+            GetLogString(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD,
+                         "Hello World {0}", 47));
+}