[FlowSensitive] Log analysis progress for debugging purposes

[sammccall]

Summary

The goal is to be able to understand how the analysis executes, and what its
incremental and final findings are, by enabling logging and reading the logs.
This should include both framework and analysis-specific information.

Ad-hoc printf-debugging doesn't seem sufficient for my understanding, at least.
Being able to check in logging, turn it on in a production binary, and quickly
find particular analysis steps within complex functions seem important.

This can be enabled programmatically through DataflowAnalysisOptions, or
via the flag -dataflow-log. (Works in unittests, clang-tidy, standalone
tools...)

Important missing pieces here:

• a logger implementation that produces an interactive report (HTML file) which can be navigated via timeline/code/CFG. (I think the Logger interface is sufficient for this, but need to prototype).
• display of the application-specific lattice
• more useful display for the built-in environment (e.g. meaningful & consistent names for values, hiding redundant variables in the flow condition, hiding unreachable expressions)

[sammccall]

A little more docs

[sammccall]

Example textual log (though better with colors):

=== Beginning data flow analysis ===
int target(int x) {
    while (x > 0)
        {
            --x;
        }
    return x + 1;
}

FunctionDecl 0x2a9a300 </usr/local/google/home/sammccall/test.cc:1:1, line:6:1> line:1:5 target 'int (int)'
|-ParmVarDecl 0x2a9a238 <col:12, col:16> col:16 used x 'int'
`-CompoundStmt 0x2a9a568 <col:19, line:6:1>
  |-WhileStmt 0x2a9a4c0 <line:2:3, line:4:3>
  | |-BinaryOperator 0x2a9a450 <line:2:10, col:12> 'bool' '>'
  | | |-ImplicitCastExpr 0x2a9a438 <col:10> 'int' <LValueToRValue>
  | | | `-DeclRefExpr 0x2a9a3f8 <col:10> 'int' lvalue ParmVar 0x2a9a238 'x' 'int'
  | | `-IntegerLiteral 0x2a9a418 <col:12> 'int' 0
  | `-CompoundStmt 0x2a9a4a8 <col:15, line:4:3>
  |   `-UnaryOperator 0x2a9a490 <line:3:5, col:7> 'int' lvalue prefix '--'
  |     `-DeclRefExpr 0x2a9a470 <col:7> 'int' lvalue ParmVar 0x2a9a238 'x' 'int'
  `-ReturnStmt 0x2a9a558 <line:5:3, col:14>
    `-BinaryOperator 0x2a9a538 <col:10, col:14> 'int' '+'
      |-ImplicitCastExpr 0x2a9a520 <col:10> 'int' <LValueToRValue>
      | `-DeclRefExpr 0x2a9a4e0 <col:10> 'int' lvalue ParmVar 0x2a9a238 'x' 'int'
      `-IntegerLiteral 0x2a9a500 <col:14> 'int' 1

 [B5 (ENTRY)]
   Succs (1): B4

 [B1]
   1: x
   2: [B1.1] (ImplicitCastExpr, LValueToRValue, int)
   3: 1
   4: [B1.2] + [B1.3]
   5: return [B1.4];
   Preds (1): B4
   Succs (1): B0

 [B2]
   Preds (1): B3
   Succs (1): B4

 [B3]
   1: x
   2: --[B3.1]
   Preds (1): B4
   Succs (1): B2

 [B4]
   1: x
   2: [B4.1] (ImplicitCastExpr, LValueToRValue, int)
   3: 0
   4: [B4.2] > [B4.3]
   T: while [B4.4]
   Preds (2): B2 B5
   Succs (2): B3 B1

 [B0 (EXIT)]
   Preds (1): B1

=== Entering block B4 (iteration 1) ===

 [B4]
   1: x
   2: [B4.1] (ImplicitCastExpr, LValueToRValue, int)
   3: 0
   4: [B4.2] > [B4.3]
   T: while [B4.4]
   Preds (2): B2 B5
   Succs (2): B3 B1

Computed state for B4.0:
DeclToLoc:
ExprToLoc:
LocToVal:
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
B0
B2

Processing element B4.1: x
transfer!
Computed state for B4.1:
DeclToLoc:
ExprToLoc:
LocToVal:
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
B0
B2

Processing element B4.2: x (ImplicitCastExpr, LValueToRValue, int)
transfer!
Computed state for B4.2:
DeclToLoc:
ExprToLoc:
LocToVal:
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
B0
B2

Processing element B4.3: 0
transfer!
Computed state for B4.3:
DeclToLoc:
ExprToLoc:
LocToVal:
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
B0
B2

Processing element B4.4: x > 0
transfer!
Computed state for B4.4:
DeclToLoc:
ExprToLoc:
LocToVal:
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
B0
B2

=== Entering block B1 (iteration 1) ===

 [B1]
   1: x
   2: [B1.1] (ImplicitCastExpr, LValueToRValue, int)
   3: 1
   4: [B1.2] + [B1.3]
   5: return [B1.4];
   Preds (1): B4
   Succs (1): B0

Computed state for B1.0:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2ab7da0: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    (and
        B0
        (not
            B5)))
(=
    B6
    B4)
B2
B6

Processing element B1.1: x
transfer!
Computed state for B1.1:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2ab7da0: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    (and
        B0
        (not
            B5)))
(=
    B6
    B4)
B2
B6

Processing element B1.2: x (ImplicitCastExpr, LValueToRValue, int)
transfer!
Computed state for B1.2:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2ab7da0: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    (and
        B0
        (not
            B5)))
(=
    B6
    B4)
B2
B6

Processing element B1.3: 1
transfer!
Computed state for B1.3:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2ab7da0: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    (and
        B0
        (not
            B5)))
(=
    B6
    B4)
B2
B6

Processing element B1.4: x + 1
transfer!
Computed state for B1.4:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2ab7da0: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    (and
        B0
        (not
            B5)))
(=
    B6
    B4)
B2
B6

Processing element B1.5: return x + 1;
transfer!
Computed state for B1.5:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2ab7da0: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    (and
        B0
        (not
            B5)))
(=
    B6
    B4)
B2
B6

=== Entering block B0 (iteration 1) ===

 [B0 (EXIT)]
   Preds (1): B1

Computed state for B0.0:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2ab7da0: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    (and
        B0
        (not
            B5)))
(=
    B6
    B4)
(=
    B7
    B8)
(=
    B8
    B6)
B2
B7

=== Entering block B3 (iteration 1) ===

 [B3]
   1: x
   2: --[B3.1]
   Preds (1): B4
   Succs (1): B2

Computed state for B3.0:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2aba810: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    B5)
(=
    B5
    (and
        B0
        B6))
B2
B4

Processing element B3.1: x
transfer!
Computed state for B3.1:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2aba810: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    B5)
(=
    B5
    (and
        B0
        B6))
B2
B4

Processing element B3.2: --x
transfer!
Computed state for B3.2:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2aba810: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    B5)
(=
    B5
    (and
        B0
        B6))
B2
B4

=== Entering block B2 (iteration 1) ===

 [B2]
   Preds (1): B3
   Succs (1): B4

Computed state for B2.0:
DeclToLoc:
ExprToLoc:
  [0x2a9a450, 0x2ab7e60]
LocToVal:
  [0x2ab7e60, 0x2aba810: AtomicBool]
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B3)
(=
    B3
    B2)
(=
    B4
    B5)
(=
    B5
    B7)
(=
    B6
    B4)
(=
    B7
    (and
        B0
        B8))
B2
B6

=== Entering block B4 (iteration 2) ===

 [B4]
   1: x
   2: [B4.1] (ImplicitCastExpr, LValueToRValue, int)
   3: 0
   4: [B4.2] > [B4.3]
   T: while [B4.4]
   Preds (2): B2 B5
   Succs (2): B3 B1

Computed state for B4.0:
DeclToLoc:
ExprToLoc:
LocToVal:
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B7)
(=
    B10
    (and
        B2
        B12))
(=
    B11
    (or
        B0
        B5))
(=
    B2
    B3)
(=
    B3
    B1)
(=
    B4
    B11)
(=
    B5
    B6)
(=
    B6
    B8)
(=
    B8
    B9)
(=
    B9
    B10)
B4
B7

Processing element B4.1: x
transfer!
Computed state for B4.1:
DeclToLoc:
ExprToLoc:
LocToVal:
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B7)
(=
    B10
    (and
        B2
        B12))
(=
    B11
    (or
        B0
        B5))
(=
    B2
    B3)
(=
    B3
    B1)
(=
    B4
    B11)
(=
    B5
    B6)
(=
    B6
    B8)
(=
    B8
    B9)
(=
    B9
    B10)
B4
B7

Processing element B4.2: x (ImplicitCastExpr, LValueToRValue, int)
transfer!
Computed state for B4.2:
DeclToLoc:
ExprToLoc:
LocToVal:
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B7)
(=
    B10
    (and
        B2
        B12))
(=
    B11
    (or
        B0
        B5))
(=
    B2
    B3)
(=
    B3
    B1)
(=
    B4
    B11)
(=
    B5
    B6)
(=
    B6
    B8)
(=
    B8
    B9)
(=
    B9
    B10)
B4
B7

Processing element B4.3: 0
transfer!
Computed state for B4.3:
DeclToLoc:
ExprToLoc:
LocToVal:
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B7)
(=
    B10
    (and
        B2
        B12))
(=
    B11
    (or
        B0
        B5))
(=
    B2
    B3)
(=
    B3
    B1)
(=
    B4
    B11)
(=
    B5
    B6)
(=
    B6
    B8)
(=
    B8
    B9)
(=
    B9
    B10)
B4
B7

Processing element B4.4: x > 0
transfer!
Computed state for B4.4:
DeclToLoc:
ExprToLoc:
LocToVal:
FlowConditionToken:
(=
    B0
    B1)
(=
    B1
    B7)
(=
    B10
    (and
        B2
        B12))
(=
    B11
    (or
        B0
        B5))
(=
    B2
    B3)
(=
    B3
    B1)
(=
    B4
    B11)
(=
    B5
    B6)
(=
    B6
    B8)
(=
    B8
    B9)
(=
    B9
    B10)
B4
B7

B4 has converged!
=== Finished analysis: 5 blocks in 6 total steps ===

[sammccall]

Fix colors, log source

[sammccall]

I wanted to share this to get some initial thoughts as we'd discussed debuggability a while ago.
As mentioned I'd at least want to get a reasonable HTML report before moving forward with it though.

[gribozavr2]

clang/include/clang/Analysis/FlowSensitive/Logger.h

23

Elsewhere under Analysis/FlowSensitive we use triple slash as a doc comment marker - could you make the new header follow the pattern?

24

39

Why not DataflowAnalysisContext instead of ControlFlowContext?

You can reach the latter from the former, but not vice versa.

[sammccall]

Address review comments
Added -dataflow-log flag to enable logging without code changes
Removed example tool from this patch

[sammccall]

Thanks! I cleaned up a bit and added tests, as well as a -dataflow-log flag to make this easy to access when running unit tests, tidy checks etc.
The HTML experiments seem to have validated that the logging API is sufficient to produce something useful there.

I think this is ready for proper review now.

clang/include/clang/Analysis/FlowSensitive/Logger.h

39

The idea here is "we're starting to analyze a CFG", so passing in the CFG is what we need and seems natural.
DataflowAnalysisContext provides more facilities than we need, and none of the extra stuff seems useful.
It's also more awkward to use for our purposes (you can get the CFG, but only if you know the right FunctionDecl, and the framework is unclear about whether there's always a FunctionDecl).

[NoQ]

I love such debugging facilities! They're a massive boost to developer productivity compared to ad-hoc debug prints, and they allow new contributors to study how the tool works. I'm excited to see how this thing turns out.

In the static analyzer's path-sensitive engine we've settled on a Graphviz printout of the analysis graph, with an extra python script to filter and "prettify" it. In our case these graphs are much larger than CFGs (on real-world code they often contain over 200000 nodes) so filtering and searching becomes essential. And we usually don't have an option to debug a reduced toy example, because it's typically very hard to define the notion of "false positive" in a way suitable for a creduce predicate, and even when reducing manually it's easy to miss the point entirely and end up with a completely different problem. So we had to learn how to deal with these massive graphs, and these days we're pretty good at that. In your case the graphs probably aren't that massive, but other considerations probably still apply.

I found textual CFG dumps of real-world functions to be very hard to read; it's annoying to figure out in which order you're supposed to read the blocks. Most of the time I prefer Graphviz dumps of the CFG. If you're stuck with real-world code as much as we are in the static analyzer, it might be very convenient to somehow include a graphical representation of the CFG alongside your reports. Given that CFGs are relatively small, you might be able to get away with an ad-hoc graph visualizer scripted into your HTML page, so that to avoid relying on Graphviz.

Then I guess you can try adding your abstract state information directly to the graphical CFG blocks, and build a timeline of such partially analyzed CFGs, from the starting state to the fully converged state, brightly highlighting changes made on every step 🤔Dunno, just dreaming at this point.

[sammccall]

In D144730#4211222, @NoQ wrote:

I love such debugging facilities! They're a massive boost to developer productivity compared to ad-hoc debug prints, and they allow new contributors to study how the tool works. I'm excited to see how this thing turns out.

Thanks! It's great to know this is a problem worth some attention, as any tools here will carry some complexity.

In the static analyzer's path-sensitive engine we've settled on a Graphviz printout of the analysis graph, with an extra python script to filter and "prettify" it. In our case these graphs are much larger than CFGs (on real-world code they often contain over 200000 nodes) so filtering and searching becomes essential. And we usually don't have an option to debug a reduced toy example, because it's typically very hard to define the notion of "false positive" in a way suitable for a creduce predicate, and even when reducing manually it's easy to miss the point entirely and end up with a completely different problem. So we had to learn how to deal with these massive graphs, and these days we're pretty good at that. In your case the graphs probably aren't that massive, but other considerations probably still apply.

Yeah, as I understand the dataflow analysis proper is scoped to a function, so dealing with larger CFGs but not on that scale. I'm hoping that graphviz renderings of the CFG + overlaying it on the code are enough. Text dumps are indeed too difficult to read until you're really zeroed in on the bit you want to look at.

If you're stuck with real-world code as much as we are in the static analyzer, it might be very convenient to somehow include a graphical representation of the CFG alongside your reports. Given that CFGs are relatively small, you might be able to get away with an ad-hoc graph visualizer scripted into your HTML page, so that to avoid relying on Graphviz.

Here's a prototype I put together: https://htmlpreview.github.io/?https://gist.githubusercontent.com/sam-mccall/c03943495d2ca493be8f3087c22e3b70/raw/986a1d7d9e1ff37e46fc9b6808f0650ae28cc8d3/analyze_optional.html

I tried the ad-hoc method like you suggest to avoid the dependency, but working out how to place the nodes & arcs reasonably quickly looked too much for me. Ended up going back to shelling out to graphviz but embedding the result in the page.

Then I guess you can try adding your abstract state information directly to the graphical CFG blocks, and build a timeline of such partially analyzed CFGs, from the starting state to the fully converged state, brightly highlighting changes made on every step 🤔Dunno, just dreaming at this point.

Yes! This is very much where I want to go. I'll have an initial version up soon with basic functionality (timeline, CFG, simple textual dump at each point) but showing the most relevant state and changes at each point would be really useful.

[xazax.hun]

clang/include/clang/Analysis/FlowSensitive/DataflowEnvironment.h

186

If we already have a NullLogger, I wonder if making DACtx->getOptions().Log a reference that points to NullLogger when logging is disabled would be less confusing (and fewer branches).

[xazax.hun]

clang/lib/Analysis/FlowSensitive/Logger.cpp

18

Adding final? Just in case it can help with devirtualization.

24

final?

[sammccall]

address review comments

clang/include/clang/Analysis/FlowSensitive/DataflowEnvironment.h

186

Made the DataAnalysisContext constructor fill in this field with NullLogger if there isn't anything else, to avoid the branch. (Added a comment on the field).

It's still a pointer because of the ergonomic problems with ref fields in structs like this (can't initialize incrementally), and because we need a value for "no programmatic logging requested, feel free to respect the -dataflow-log flag" and using Logger::null() as a sentinel seems pretty surprising.

[ymandel]

Awesome, thanks!

clang/include/clang/Analysis/FlowSensitive/Logger.h

19

Maybe comment on the need for these vs including the headers.

clang/lib/Analysis/FlowSensitive/DataflowAnalysisContext.cpp

394

nit: > 0?

clang/include/clang/Analysis/FlowSensitive/DataflowAnalysisContext.h

 #include <memory>
 #include <optional>
 #include <type_traits>
 #include <utility>
 #include <vector>
 
 namespace clang {
 namespace dataflow {
+class Logger;
 
 /// Skip past nodes that the CFG does not emit. These nodes are invisible to
 /// flow-sensitive analysis, and should be ignored as they will effectively not
 /// exist.
 ///
 ///   * `ParenExpr` - The CFG takes the operator precedence into account, but
 ///   otherwise omits the node afterwards.
 ///

 class DataflowAnalysisContext {
 public:
   struct Options {
     /// Options for analyzing function bodies when present in the translation
     /// unit, or empty to disable context-sensitive analysis. Note that this is
     /// fundamentally limited: some constructs, such as recursion, are
     /// explicitly unsupported.
     std::optional<ContextSensitiveOptions> ContextSensitiveOpts;
+
+    /// If provided, analysis details will be recorded here.
+    /// (This is always non-null within an AnalysisContext, the framework
+    /// provides a fallback no-op logger).
+    Logger *Log = nullptr;
   };
 
   /// Constructs a dataflow analysis context.
   ///
   /// Requirements:
   ///
   ///  `S` must not be null.
   DataflowAnalysisContext(std::unique_ptr<Solver> S,
                           Options Opts = Options{
-                              /*ContextSensitiveOpts=*/std::nullopt})
-      : S(std::move(S)), TrueVal(createAtomicBoolValue()),
-        FalseVal(createAtomicBoolValue()), Opts(Opts) {
-    assert(this->S != nullptr);
-  }
+                              /*ContextSensitiveOpts=*/std::nullopt,
+                              /*Logger=*/nullptr});
+  ~DataflowAnalysisContext();
 
   /// Takes ownership of `Loc` and returns a reference to it.
   ///
   /// Requirements:
   ///
   ///  `Loc` must not be null.
   template <typename T>
   std::enable_if_t<std::is_base_of<StorageLocation, T>::value, T &>
private:
   llvm::DenseMap<AtomicBoolValue *, llvm::DenseSet<AtomicBoolValue *>>
       FlowConditionDeps;
   llvm::DenseMap<AtomicBoolValue *, BoolValue *> FlowConditionConstraints;
 
   llvm::DenseMap<const FunctionDecl *, ControlFlowContext> FunctionContexts;
 
   // Fields modeled by environments covered by this context.
   llvm::DenseSet<const FieldDecl *> ModeledFields;
+
+  std::unique_ptr<Logger> LogOwner; // If created via flags.
 };
 
 } // namespace dataflow
 } // namespace clang
 
 #endif // LLVM_CLANG_ANALYSIS_FLOWSENSITIVE_DATAFLOWANALYSISCONTEXT_H

clang/include/clang/Analysis/FlowSensitive/DataflowEnvironment.h

 
 #include "clang/AST/Decl.h"
 #include "clang/AST/DeclBase.h"
 #include "clang/AST/Expr.h"
 #include "clang/AST/Type.h"
 #include "clang/Analysis/FlowSensitive/ControlFlowContext.h"
 #include "clang/Analysis/FlowSensitive/DataflowAnalysisContext.h"
 #include "clang/Analysis/FlowSensitive/DataflowLattice.h"
+#include "clang/Analysis/FlowSensitive/Logger.h"
 #include "clang/Analysis/FlowSensitive/StorageLocation.h"
 #include "clang/Analysis/FlowSensitive/Value.h"
 #include "llvm/ADT/DenseMap.h"
 #include "llvm/ADT/DenseSet.h"
 #include "llvm/Support/ErrorHandling.h"
 #include <memory>
 #include <type_traits>
 #include <utility>
public:
   ///
   /// If `DeclCtx` is a function, initializes the environment with symbolic
   /// representations of the function parameters.
   ///
   /// If `DeclCtx` is a non-static member function, initializes the environment
   /// with a symbolic representation of the `this` pointee.
   Environment(DataflowAnalysisContext &DACtx, const DeclContext &DeclCtx);
 
-  const DataflowAnalysisContext::Options &getAnalysisOptions() {
+  const DataflowAnalysisContext::Options &getAnalysisOptions() const {
     return DACtx->getOptions();
   }
 
+  Logger &logger() const { return *DACtx->getOptions().Log; }
+
   /// Creates and returns an environment to use for an inline analysis  of the
   /// callee. Uses the storage location from each argument in the `Call` as the
   /// storage location for the corresponding parameter in the callee.
   ///
   /// Requirements:
   ///
   ///  The callee of `Call` must be a `FunctionDecl`.
   ///

clang/include/clang/Analysis/FlowSensitive/Logger.h

+//===-- Logger.h ------------------------------------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef LLVM_CLANG_ANALYSIS_FLOWSENSITIVE_LOGGER_H
+#define LLVM_CLANG_ANALYSIS_FLOWSENSITIVE_LOGGER_H
+
+#include "clang/Analysis/CFG.h"
+#include "llvm/Support/raw_ostream.h"
+#include <memory>
+
+namespace clang::dataflow {
+// Forward declarations so we can use Logger anywhere in the framework.
+class ControlFlowContext;
+class TypeErasedDataflowAnalysis;
+struct TypeErasedDataflowAnalysisState;
+
+/// A logger is notified as the analysis progresses.
+/// It can produce a report of the analysis's findings and how it came to them.
+///
+/// The framework reports key structural events (e.g. traversal of blocks).
+/// The specific analysis can add extra details to be presented in context.
+class Logger {
+public:
+  /// Returns a dummy logger that does nothing.
+  static Logger &null();
+  /// A logger that simply writes messages to the specified ostream in real
+  /// time.
+  static std::unique_ptr<Logger> textual(llvm::raw_ostream &);
+
+  virtual ~Logger() = default;
+
+  /// Called by the framework as we start analyzing a new function or statement.
+  /// Forms a pair with endAnalysis().
+  virtual void beginAnalysis(const ControlFlowContext &,
+                             TypeErasedDataflowAnalysis &) {}
+  virtual void endAnalysis() {}
+
+  // At any time during the analysis, we're computing the state for some target
+  // program point.
+
+  /// Called when we start (re-)processing a block in the CFG.
+  /// The target program point is the entry to the specified block.
+  /// Calls to log() describe transferBranch(), join() etc.
+  virtual void enterBlock(const CFGBlock &) {}
+  /// Called when we start processing an element in the current CFG block.
+  /// The target program point is after the specified element.
+  /// Calls to log() describe the transfer() function.
+  virtual void enterElement(const CFGElement &) {}
+
+  /// Records the analysis state computed for the current program point.
+  virtual void recordState(TypeErasedDataflowAnalysisState &) {}
+  /// Records that the analysis state for the current block is now final.
+  virtual void blockConverged() {}
+
+  /// Called by the framework or user code to report some event.
+  /// The event is associated with the current context (program point).
+  /// The Emit function produces the log message. It may or may not be called,
+  /// depending on if the logger is interested; it should have no side effects.
+  void log(llvm::function_ref<void(llvm::raw_ostream &)> Emit) {
+    if (!ShouldLogText)
+      return;
+    std::string S;
+    llvm::raw_string_ostream OS(S);
+    Emit(OS);
+    logText(S);
+  }
+
+protected:
+  /// ShouldLogText should be false for trivial loggers that ignore logText().
+  /// This allows log() to skip evaluating its Emit function.
+  Logger(bool ShouldLogText = true) : ShouldLogText(ShouldLogText) {}
+
+private:
+  bool ShouldLogText;
+  virtual void logText(llvm::StringRef) {}
+};
+
+} // namespace clang::dataflow
+
+#endif

clang/lib/Analysis/FlowSensitive/CMakeLists.txt

 add_clang_library(clangAnalysisFlowSensitive
   ControlFlowContext.cpp
   DataflowAnalysisContext.cpp
   DataflowEnvironment.cpp
+  Logger.cpp
   Transfer.cpp
   TypeErasedDataflowAnalysis.cpp
   Value.cpp
   WatchedLiteralsSolver.cpp
   DebugSupport.cpp
 
   LINK_LIBS
   clangAnalysis
   clangAST
   clangBasic
   )
 
 add_subdirectory(Models)

clang/lib/Analysis/FlowSensitive/DataflowAnalysisContext.cpp

 //  encompass the state of a program and stores context that is used during
 //  dataflow analysis.
 //
 //===----------------------------------------------------------------------===//
 
 #include "clang/Analysis/FlowSensitive/DataflowAnalysisContext.h"
 #include "clang/AST/ExprCXX.h"
 #include "clang/Analysis/FlowSensitive/DebugSupport.h"
+#include "clang/Analysis/FlowSensitive/Logger.h"
 #include "clang/Analysis/FlowSensitive/Value.h"
 #include "llvm/ADT/SetOperations.h"
+#include "llvm/Support/CommandLine.h"
 #include "llvm/Support/Debug.h"
 #include <cassert>
 #include <memory>
 #include <utility>
 
+static llvm::cl::opt<std::string>
+    DataflowLog("dataflow-log", llvm::cl::Hidden, llvm::cl::ValueOptional,
+                llvm::cl::desc("Emit log of dataflow analysis. With no arg, "
+                               "writes textual log to stderr."));
+
 namespace clang {
 namespace dataflow {
 
 void DataflowAnalysisContext::addModeledFields(
     const llvm::DenseSet<const FieldDecl *> &Fields) {
   llvm::set_union(ModeledFields, Fields);
 }
 
if (Stmt *Body = F->getBody()) {
     assert(CFCtx);
     auto Result = FunctionContexts.insert({F, std::move(*CFCtx)});
     return &Result.first->second;
   }
 
   return nullptr;
 }
 
+DataflowAnalysisContext::DataflowAnalysisContext(std::unique_ptr<Solver> S,
+                                                 Options Opts)
+    : S(std::move(S)), TrueVal(createAtomicBoolValue()),
+      FalseVal(createAtomicBoolValue()), Opts(Opts) {
+  assert(this->S != nullptr);
+  // If the -dataflow-log command-line flag was set, synthesize a logger.
+  // This is ugly but provides a uniform method for ad-hoc debugging dataflow-
+  // based tools.
+  if (Opts.Log == nullptr) {
+    if (DataflowLog.getNumOccurrences() > 0) {
+      LogOwner = Logger::textual(llvm::errs());
+      this->Opts.Log = LogOwner.get();
+      // FIXME: if the flag is given a value, write an HTML log to a file.
+    } else {
+      this->Opts.Log = &Logger::null();
+    }
+  }
+}
+
+DataflowAnalysisContext::~DataflowAnalysisContext() = default;
+
 } // namespace dataflow
 } // namespace clang
 
 using namespace clang;
 
 const Expr &clang::dataflow::ignoreCFGOmittedNodes(const Expr &E) {
   const Expr *Current = &E;
   if (auto *EWC = dyn_cast<ExprWithCleanups>(Current)) {

clang/lib/Analysis/FlowSensitive/Logger.cpp

+//===-- Logger.cpp --------------------------------------------------------===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+
+#include "clang/Analysis/FlowSensitive/Logger.h"
+#include "clang/Analysis/FlowSensitive/ControlFlowContext.h"
+#include "clang/Analysis/FlowSensitive/TypeErasedDataflowAnalysis.h"
+#include "llvm/Support/WithColor.h"
+
+namespace clang::dataflow {
+
+Logger &Logger::null() {
+  struct NullLogger final : Logger {};
+  static auto *Instance = new NullLogger();
+  return *Instance;
+}
+
+namespace {
+struct TextualLogger final : Logger {
+  llvm::raw_ostream &OS;
+  const CFG *CurrentCFG;
+  const CFGBlock *CurrentBlock;
+  const CFGElement *CurrentElement;
+  unsigned CurrentElementIndex;
+  bool ShowColors;
+  llvm::DenseMap<const CFGBlock *, unsigned> VisitCount;
+  TypeErasedDataflowAnalysis *CurrentAnalysis;
+
+  TextualLogger(llvm::raw_ostream &OS)
+      : OS(OS), ShowColors(llvm::WithColor::defaultAutoDetectFunction()(OS)) {}
+
+  virtual void beginAnalysis(const ControlFlowContext &CFG,
+                             TypeErasedDataflowAnalysis &Analysis) override {
+    {
+      llvm::WithColor Header(OS, llvm::raw_ostream::Colors::RED, /*Bold=*/true);
+      OS << "=== Beginning data flow analysis ===\n";
+    }
+    if (auto *D = CFG.getDecl()) {
+      D->print(OS);
+      OS << "\n";
+      D->dump(OS);
+    }
+    CurrentCFG = &CFG.getCFG();
+    CurrentCFG->print(OS, Analysis.getASTContext().getLangOpts(), ShowColors);
+    CurrentAnalysis = &Analysis;
+  }
+  virtual void endAnalysis() override {
+    llvm::WithColor Header(OS, llvm::raw_ostream::Colors::RED, /*Bold=*/true);
+    unsigned Blocks = 0, Steps = 0;
+    for (const auto &E : VisitCount) {
+      ++Blocks;
+      Steps += E.second;
+    }
+    llvm::errs() << "=== Finished analysis: " << Blocks << " blocks in "
+                 << Steps << " total steps ===\n";
+  }
+  virtual void enterBlock(const CFGBlock &Block) override {
+    unsigned Count = ++VisitCount[&Block];
+    {
+      llvm::WithColor Header(OS, llvm::raw_ostream::Colors::RED, /*Bold=*/true);
+      OS << "=== Entering block B" << Block.getBlockID() << " (iteration "
+         << Count << ") ===\n";
+    }
+    Block.print(OS, CurrentCFG, CurrentAnalysis->getASTContext().getLangOpts(),
+                ShowColors);
+    CurrentBlock = &Block;
+    CurrentElement = nullptr;
+    CurrentElementIndex = 0;
+  }
+  virtual void enterElement(const CFGElement &Element) override {
+    ++CurrentElementIndex;
+    CurrentElement = &Element;
+    {
+      llvm::WithColor Subheader(OS, llvm::raw_ostream::Colors::CYAN,
+                                /*Bold=*/true);
+      OS << "Processing element B" << CurrentBlock->getBlockID() << "."
+         << CurrentElementIndex << ": ";
+      Element.dumpToStream(OS);
+    }
+  }
+  void recordState(TypeErasedDataflowAnalysisState &State) override {
+    {
+      llvm::WithColor Subheader(OS, llvm::raw_ostream::Colors::CYAN,
+                                /*Bold=*/true);
+      OS << "Computed state for B" << CurrentBlock->getBlockID() << "."
+         << CurrentElementIndex << ":\n";
+    }
+    // FIXME: currently the environment dump is verbose and unenlightening.
+    // FIXME: dump the user-defined lattice, too.
+    State.Env.dump(OS);
+    OS << "\n";
+  }
+  void blockConverged() override {
+    OS << "B" << CurrentBlock->getBlockID() << " has converged!\n";
+  }
+  virtual void logText(llvm::StringRef S) override { OS << S << "\n"; }
+};
+} // namespace
+
+std::unique_ptr<Logger> Logger::textual(llvm::raw_ostream &OS) {
+  return std::make_unique<TextualLogger>(OS);
+}
+
+} // namespace clang::dataflow

clang/lib/Analysis/FlowSensitive/TypeErasedDataflowAnalysis.cpp

 /// Holds data structures required for running dataflow analysis.
 struct AnalysisContext {
   AnalysisContext(const ControlFlowContext &CFCtx,
                   TypeErasedDataflowAnalysis &Analysis,
                   const Environment &InitEnv,
                   llvm::ArrayRef<std::optional<TypeErasedDataflowAnalysisState>>
                       BlockStates)
       : CFCtx(CFCtx), Analysis(Analysis), InitEnv(InitEnv),
-        BlockStates(BlockStates) {}
+        Log(InitEnv.logger()), BlockStates(BlockStates) {
+    Log.beginAnalysis(CFCtx, Analysis);
+  }
+  ~AnalysisContext() { Log.endAnalysis(); }
 
   /// Contains the CFG being analyzed.
   const ControlFlowContext &CFCtx;
   /// The analysis to be run.
   TypeErasedDataflowAnalysis &Analysis;
   /// Initial state to start the analysis.
   const Environment &InitEnv;
+  Logger &Log;
   /// Stores the state of a CFG block if it has been evaluated by the analysis.
   /// The indices correspond to the block IDs.
   llvm::ArrayRef<std::optional<TypeErasedDataflowAnalysisState>> BlockStates;
 };
 
 /// Computes the input state for a given basic block by joining the output
 /// states of its predecessors.
 ///

 /// user-specified analysis.
 /// `PostVisitCFG` (if provided) will be applied to the element after evaluation
 /// by the user-specified analysis.
 TypeErasedDataflowAnalysisState
 transferCFGBlock(const CFGBlock &Block, AnalysisContext &AC,
                  std::function<void(const CFGElement &,
                                     const TypeErasedDataflowAnalysisState &)>
                      PostVisitCFG = nullptr) {
+  AC.Log.enterBlock(Block);
   auto State = computeBlockInputState(Block, AC);
+  AC.Log.recordState(State);
   for (const auto &Element : Block) {
+    AC.Log.enterElement(Element);
     // Built-in analysis
     if (AC.Analysis.builtinOptions()) {
       builtinTransfer(Element, State, AC);
     }
 
     // User-provided analysis
     AC.Analysis.transferTypeErased(Element, State.Lattice, State.Env);
 
     // Post processing
     if (PostVisitCFG) {
       PostVisitCFG(Element, State);
     }
+    AC.Log.recordState(State);
   }
   return State;
 }
 
 TypeErasedDataflowAnalysisState transferBlock(
     const ControlFlowContext &CFCtx,
     llvm::ArrayRef<std::optional<TypeErasedDataflowAnalysisState>> BlockStates,
     const CFGBlock &Block, const Environment &InitEnv,
if (OldBlockState) {
         OldBlockState->Env.dump();
       });
       if (isLoopHead(*Block)) {
         LatticeJoinEffect Effect1 = Analysis.widenTypeErased(
             NewBlockState.Lattice, OldBlockState->Lattice);
         LatticeJoinEffect Effect2 =
             NewBlockState.Env.widen(OldBlockState->Env, Analysis);
         if (Effect1 == LatticeJoinEffect::Unchanged &&
-            Effect2 == LatticeJoinEffect::Unchanged)
+            Effect2 == LatticeJoinEffect::Unchanged) {
           // The state of `Block` didn't change from widening so there's no need
           // to revisit its successors.
+          AC.Log.blockConverged();
           continue;
+        }
       } else if (Analysis.isEqualTypeErased(OldBlockState->Lattice,
                                             NewBlockState.Lattice) &&
                  OldBlockState->Env.equivalentTo(NewBlockState.Env, Analysis)) {
         // The state of `Block` didn't change after transfer so there's no need
         // to revisit its successors.
+        AC.Log.blockConverged();
         continue;
       }
     }
 
     BlockStates[Block->getBlockID()] = std::move(NewBlockState);
 
     // Do not add unreachable successor blocks to `Worklist`.
     if (Block->hasNoReturnElement())

clang/unittests/Analysis/FlowSensitive/CMakeLists.txt

 set(LLVM_LINK_COMPONENTS
   FrontendOpenMP
   Support
   )
 
 add_clang_unittest(ClangAnalysisFlowSensitiveTests
   CFGMatchSwitchTest.cpp
   ChromiumCheckModelTest.cpp
   DataflowAnalysisContextTest.cpp
   DataflowEnvironmentTest.cpp
   DebugSupportTest.cpp
+  LoggerTest.cpp
   MapLatticeTest.cpp
   MatchSwitchTest.cpp
   MultiVarConstantPropagationTest.cpp
   SignAnalysisTest.cpp
   SingleVarConstantPropagationTest.cpp
   SolverTest.cpp
   TestingSupport.cpp
   TestingSupportTest.cpp

clang/unittests/Analysis/FlowSensitive/LoggerTest.cpp

+#include "TestingSupport.h"
+#include "clang/ASTMatchers/ASTMatchers.h"
+#include "clang/Analysis/FlowSensitive/DataflowAnalysis.h"
+#include "clang/Analysis/FlowSensitive/DataflowEnvironment.h"
+#include "clang/Analysis/FlowSensitive/DataflowLattice.h"
+#include "llvm/Testing/Support/Error.h"
+#include "gtest/gtest.h"
+#include <optional>
+
+namespace clang::dataflow::test {
+namespace {
+
+struct TestLattice {
+  int Elements = 0;
+  int Branches = 0;
+  int Joins = 0;
+
+  LatticeJoinEffect join(const TestLattice &Other) {
+    if (Joins < 3) {
+      ++Joins;
+      Elements += Other.Elements;
+      Branches += Other.Branches;
+      return LatticeJoinEffect::Changed;
+    }
+    return LatticeJoinEffect::Unchanged;
+  }
+  friend bool operator==(const TestLattice &LHS, const TestLattice &RHS) {
+    return std::tie(LHS.Elements, LHS.Branches, LHS.Joins) ==
+           std::tie(RHS.Elements, RHS.Branches, RHS.Joins);
+  }
+};
+
+class TestAnalysis : public DataflowAnalysis<TestAnalysis, TestLattice> {
+public:
+  using DataflowAnalysis::DataflowAnalysis;
+
+  static TestLattice initialElement() { return TestLattice{}; }
+  void transfer(const CFGElement &, TestLattice &L, Environment &E) {
+    E.logger().log([](llvm::raw_ostream &OS) { OS << "transfer()"; });
+    ++L.Elements;
+  }
+  void transferBranch(bool Branch, const Stmt *S, TestLattice &L,
+                      Environment &E) {
+    E.logger().log([&](llvm::raw_ostream &OS) {
+      OS << "transferBranch(" << Branch << ")";
+    });
+    ++L.Branches;
+  }
+};
+
+class TestLogger : public Logger {
+public:
+  TestLogger(std::string &S) : OS(S) {}
+
+private:
+  llvm::raw_string_ostream OS;
+
+  void beginAnalysis(const ControlFlowContext &,
+                     TypeErasedDataflowAnalysis &) override {
+    logText("beginAnalysis()");
+  }
+  void endAnalysis() override { logText("\nendAnalysis()"); }
+
+  void enterBlock(const CFGBlock &B) override {
+    OS << "\nenterBlock(" << B.BlockID << ")\n";
+  }
+  void enterElement(const CFGElement &E) override {
+    // we don't want the trailing \n
+    std::string S;
+    llvm::raw_string_ostream SS(S);
+    E.dumpToStream(SS);
+
+    OS << "enterElement(" << llvm::StringRef(S).trim() << ")\n";
+  }
+  void recordState(TypeErasedDataflowAnalysisState &S) override {
+    const TestLattice &L = llvm::any_cast<TestLattice>(S.Lattice.Value);
+    OS << "recordState(Elements=" << L.Elements << ", Branches=" << L.Branches
+       << ", Joins=" << L.Joins << ")\n";
+  }
+  /// Records that the analysis state for the current block is now final.
+  void blockConverged() override { logText("blockConverged()"); }
+
+  void logText(llvm::StringRef Text) override { OS << Text << "\n"; }
+};
+
+TEST(LoggerTest, Sequence) {
+  const char *Code = R"cpp(
+int target(bool b, int p, int q) {
+  return b ? p : q;    
+}
+)cpp";
+
+  auto Inputs = AnalysisInputs<TestAnalysis>(
+      Code, ast_matchers::hasName("target"),
+      [](ASTContext &C, Environment &) { return TestAnalysis(C); });
+  std::vector<std::string> Args = {
+      "-fsyntax-only", "-fno-delayed-template-parsing", "-std=c++17"};
+  Inputs.ASTBuildArgs = Args;
+  std::string Log;
+  TestLogger Logger(Log);
+  Inputs.BuiltinOptions.Log = &Logger;
+
+  ASSERT_THAT_ERROR(checkDataflow<TestAnalysis>(std::move(Inputs),
+                                                [](const AnalysisOutputs &) {}),
+                    llvm::Succeeded());
+
+  EXPECT_EQ(Log, R"(beginAnalysis()
+
+enterBlock(4)
+recordState(Elements=0, Branches=0, Joins=0)
+enterElement(b)
+transfer()
+recordState(Elements=1, Branches=0, Joins=0)
+enterElement(b (ImplicitCastExpr, LValueToRValue, _Bool))
+transfer()
+recordState(Elements=2, Branches=0, Joins=0)
+
+enterBlock(3)
+transferBranch(0)
+recordState(Elements=2, Branches=1, Joins=0)
+enterElement(q)
+transfer()
+recordState(Elements=3, Branches=1, Joins=0)
+
+enterBlock(2)
+transferBranch(1)
+recordState(Elements=2, Branches=1, Joins=0)
+enterElement(p)
+transfer()
+recordState(Elements=3, Branches=1, Joins=0)
+
+enterBlock(1)
+recordState(Elements=6, Branches=2, Joins=1)
+enterElement(b ? p : q)
+transfer()
+recordState(Elements=7, Branches=2, Joins=1)
+enterElement(b ? p : q (ImplicitCastExpr, LValueToRValue, int))
+transfer()
+recordState(Elements=8, Branches=2, Joins=1)
+enterElement(return b ? p : q;)
+transfer()
+recordState(Elements=9, Branches=2, Joins=1)
+
+enterBlock(0)
+recordState(Elements=9, Branches=2, Joins=1)
+
+endAnalysis()
+)");
+}
+
+} // namespace
+} // namespace clang::dataflow::test