[clang] [clang][DependencyScanning] Logging Dependency Scanning Events (PR #195896)

[Qiongsi Wu via cfe-commits]

================
@@ -0,0 +1,58 @@
+// Test logging events for the scan-by-name path using CompilerInstanceWithContext.
+// This test also covers the case where the compiler spawns a new thread to scan
+// an included module.
+// Specifically, when the compiler scans dependency for module N on thread TID1,
+// it creates a different thread TID2 to scan for M. TID2 discovers that M has
+// been built, picks up the up-to-date pcm, and returns back to TID1.
+// RUN: rm -rf %t
+// RUN: split-file %s %t
+// RUN: sed -e "s|DIR|%/t|g" %t/cdb.json.template > %t/cdb.json
+
+// RUN: clang-scan-deps -compilation-database %t/cdb.json \
+// RUN:   -format experimental-full -log-path=%t/scan.log -j 1 \
+// RUN:   -module-names=M,N -o %t/deps.json
+// RUN: FileCheck %s < %t/scan.log
+
+// CHECK: [{{[0-9]+\.[0-9]+}}] [[#PID:]] [[#TID1:]]: init_compiler_instance_with_context:{{.*}}
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: start scan_by_name: M
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_read: {{.*}}[[MPCMFILE:.*\.pcm]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_write: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_write: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_add_built: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_read: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_cached: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_finalized: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: finish scan_by_name: M
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: start scan_by_name: N
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_read: {{.*}}[[NPCMFILE:.*\.pcm]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_cached: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_disk: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID2:]]: timestamp_read: {{.*}}[[MPCMFILE]]
----------------
qiongsiwu wrote:

The comment at the top of the test tries to explain this situation - TID2 is created by the compiler instance to perform module compilation. This is not a parallel scan. Thus we know that these events are deterministically sequential. I agree that this is not obvious so I added a new event `pcm_compile` so that we can link the parent thread with the thread that performs the compile in the log.  

https://github.com/llvm/llvm-project/pull/195896