[support] Prepare TimeProfiler for cross-thread support

[mbs-modular]

Summary

This NFC prepares the TimeProfiler to support the construction
and completion of time profiling 'entries' across threads.

Add ClockType alias so we can change the clock in one place.
(trivial) Use c++ usings instead of typedefs
Rename Entry to TimeTraceProfilerEntry since this type will eventually become public.
Add an intro comment.
Add some smoke unit tests.

[mbs-modular]

• woops, BeginningOfTime must always capture now according to the system clock, irrespective of what we use for the profiling clock.

[mbs-modular]

• Learning arc the hard way.

[russell.gallop]

Thanks for splitting this out. Generally looks good with some comments, and thanks for adding the unit test.

llvm/include/llvm/Support/TimeProfiler.h

53

Thanks for adding some guidance on how this is intended to be used.

I think that this could be slightly clearer/less ambiguous. timeTraceProfilerInitialize and timeTraceProfilerFinishThread should wrap the code in the thread, they shouldn't wrap thread creation.

Likewise with the main process, Initialize/Write and Cleanup are still inside the process. Wrapping the process sounds, to me, like it should be somehow outside of the process. Maybe there is a better way to phrase this, something like wrapping the code rather than the process maybe.

62

I haven't tried it but which trace viewer is best seems subjective!

Note that clang/docs/ClangCommandLineReference.rst suggests chrome://tracing or Speedscope so this could be seen to be a bit inconsistent.

llvm/unittests/Support/TimeProfilerTest.cpp

2

Stale comment.

9

smoke tests?

37

Is there a reason not to use SetUp() and TearDown() (https://github.com/google/googletest/blob/main/docs/primer.md#writing-the-main-function)? They would then be run automatically rather than having to be in each test, making it easier to add new tests.

[mbs-modular]

• Russell's comments

llvm/include/llvm/Support/TimeProfiler.h

53

Done.

62

Done. However no luck getting Speedscope to work (stack overflow) so I'll mention it with qualification.

llvm/unittests/Support/TimeProfilerTest.cpp

37

Ah, because in the sequel I want to test the explicit entry creation and ending is a no-op if no profiling has been set up. Added a very dummy test here to set the stage for that.

[mbs-modular]

Thanks again @russell.gallop, PTAL. BTW am I using arc right? arc diff HEAD~3 --update D133153 seems wrong.

[russell.gallop]

Thanks again @russell.gallop, PTAL.

I noticed a warning:

F:\git\llvm-project\llvm\lib\Support\TimeProfiler.cpp(75,3): warning: explicitly defaulted default constructor is implicitly deleted [-Wdefaulted-function-deleted]
  TimeTraceProfilerEntry() = default;
  ^
F:\git\llvm-project\llvm\lib\Support\TimeProfiler.cpp(69,23): note: default constructor of 'TimeTraceProfilerEntry' is implicitly deleted because field 'Start' of const-qualified type 'const (anonymous namespace)::TimePointType' (aka 'const time_point<std::chrono::steady_clock>') would not be initialized
  const TimePointType Start;
                      ^
1 warning generated.

Please could you fix that?

BTW am I using arc right? arc diff HEAD~3 --update D133153 seems wrong.

I don't really know as I haven't used arc. I can't see the fix for a few of my comments (e.g. header line of unit test file) so maybe it didn't pick everything up.

I did some experiments compiling a test file. Without this patch there's a difference of < 1% with and without -ftime-trace. With this patch I see around 2% performance impact from adding -ftime-trace. I'm measuring the whole time with hyperfine on Windows. Maybe this is just in the noise. Do you see a similar effect?

[mbs-modular]

• woops, BeginningOfTime must always capture now according to the system
• Russell's comments
• Missed two of Russell's comments

[mbs-modular]

Thx again @russell.gallop

I noticed a warning:

That's a strange one -- can't repro with gcc or stock clang (14) on linux, so perhaps a windows stdlib quirk? The default std::chrono::time_point ctor has been there since c++11, and we explicitly invoke it in a few places, so I'll assume this is a bug we need to work around. So reverted the triggering change.

I did some experiments compiling a test file.

I did introduce an extra std::move level for the overall entry so perhaps I'm being too optimistic with perfect forwarding? Let's avoid the issue entirely and go back to exactly the original impl so that any such cost is only paid for by those who want to use the explicit entry API I'll introduce in the sequel.

PTAL, thx.

[mbs-modular]

• Project even the default StringRef ctor

[russell.gallop]

Something is definitely up now. With the latest patch I see a 12% decrease in performance when using -ftime-trace! With 10 runs there is no overlap between the with and without timings. Are you able to reproduce this difference on a test file?

Some details in case they're important:
Applying patch on top of 0431eb59dfa8f77e460c282dd15006b363d5dbd7
Building with clang-cl+lld-link 12.0.1 on Windows based on VS2019
Building in RelWithDebInfo configuration

[mbs-modular]

This is very disturbing!

On my ubuntu box, with Release build:

CMD="/home/mbs/github/mbs-llvm-project/build/bin/clang++ -DGTEST_HAS_RTTI=0 -D_GNU_SOURCE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -I/home/mbs/github/mbs-llvm-project/build/lib/Support -I/home/mbs/github/mbs-llvm-project/llvm/lib/Support -I/home/mbs/github/mbs-llvm-project/build/include -I/home/mbs/github/mbs-llvm-project/llvm/include -fPIC -fno-semantic-interposition -fvisibility-inlines-hidden -Werror=date-time -Werror=unguarded-availability-new -Wall -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -pedantic -Wno-long-long -Wc++98-compat-extra-semi -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported -fdiagnostics-color -ffunction-sections -fdata-sections -Werror=global-constructors -O3 -DNDEBUG -std=c++17  -fno-exceptions -fno-rtti -MD -MT lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o -MF lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o.d -o lib/Support/CMakeFiles/LLVMSupport.dir/TimeProfiler.cpp.o -c /home/mbs/github/mbs-llvm-project/llvm/lib/Support/TimeProfiler.cpp"

Then for i in {1..5}; do /usr/bin/time -f "%e" $CMD; done
vs for i in {1..5}; do /usr/bin/time -f "%e" $CMD -ftime-trace; done
shows a consistent x1.03 slowdown for clang-14, my main (94c6dfbaebbd5b9474794b2437757dfb6aedefc3) and this branch (d94302069f893f0183fc3053255e287b5e7cc070).

That's comparable to the variance I see between individual runs. So I think it's in the noise for me.

Possibilities:

• Accidentally changed the clock.
• Despite all the profile writing code not depending on raw_pwrite_stream statically, there's some magic that saves profile writing time
• I'm not looking at a large enough run.

[mbs-modular]

Afraid I'm out of ideas.

Accidentally changed the clock.

No, looks good.

Despite all the profile writing code not depending on raw_pwrite_stream statically, there's some magic that saves profile writing time

Can't detect a difference, see 'pwrite' columns below.

I'm not looking at a large enough run.

CLANG="/usr/bin/clang++-14"
CLANG="/home/mbs/github/mbs-llvm-project/build/bin/clang++"
CMD="$CLANG -DGTEST_HAS_RTTI=0 -D_GNU_SOURCE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -I/home/mbs/github/mbs-llvm-project/build/lib/Analysis -I/home/mbs/github/mbs-llvm-project/llvm/lib/Analysis -I/home/mbs/github/mbs-llvm-project/build/include -I/home/mbs/github/mbs-llvm-project/llvm/include -fPIC -fno-semantic-interposition -fvisibility-inlines-hidden -Werror=date-time -Werror=unguarded-availability-new -Wall -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -pedantic -Wno-long-long -Wc++98-compat-extra-semi -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported -fdiagnostics-color -ffunction-sections -fdata-sections -O3 -DNDEBUG  -fno-exceptions -fno-rtti -std=c++17 -MD -MT lib/Analysis/CMakeFiles/LLVMAnalysis.dir/ValueTracking.cpp.o -MF lib/Analysis/CMakeFiles/LLVMAnalysis.dir/ValueTracking.cpp.o.d -o lib/Analysis/CMakeFiles/LLVMAnalysis.dir/ValueTracking.cpp.o -c /home/mbs/github/mbs-llvm-project/llvm/lib/Analysis/ValueTracking.cpp"

Seems in the noise to me:

main	main	branch	branch	pwrite	pwrite
none	flag	none	flag	none	flag
5.7	5.74	5.55	5.69	5.58	5.61
5.65	5.71	5.52	5.67	5.54	5.57
5.61	5.82	5.98	5.74	5.3	5.53
5.66	5.84	6.49	5.72	5.45	5.53
5.8	6.11	6.1	5.86	5.36	5.62
5.77	5.68	5.78	5.71	5.39	5.52
5.76	5.88	5.57	5.84	5.39	5.56
5.77	5.75	5.87	5.92	5.41	5.46
5.78	5.79	6.03	5.87	5.41	5.52
5.73	5.77	6.53	6.07	5.44	5.5
5.71	5.66	5.58	5.94	5.39	5.55
5.64	5.61	5.6	5.87	5.43	5.53
5.76	5.65	5.49	5.7	5.38	5.55
5.62	5.59	5.52	5.69	5.32	5.52
5.64	5.74	5.69	5.76	5.32	5.55

5.71	5.74	5.69	5.76	5.39	5.53   (medians)
	1.005		1.012		1.026  (factors)

[mbs-modular]

friendly ping @russell.gallop

[mbs-modular]

• woops, BeginningOfTime must always capture now according to the system
• Russell's comments
• Missed two of Russell's comments
• Project even the default StringRef ctor

[rriddle]

Does the current diff contain all of the intended changes? All of the TimeProfiler changes look NFC. For the current diff (as displayed on phab), I'm struggling to see anything that would change compile time.

[mbs-modular]

Thanks @rriddle

Does the current diff contain all of the intended changes? All of the TimeProfiler changes look NFC.

Yes, this is it, it's supposed to be NFC, and I can't explain @russell.gallop 's claimed regression.
The only mostly-NFC change is I raised the stream type from raw_pwrite_stream to raw_ostream to help the unit tests (trivial as they are).

[rriddle]

In D133153#3787571, @mbs-modular wrote:

Thanks @rriddle

Does the current diff contain all of the intended changes? All of the TimeProfiler changes look NFC.

Yes, this is it, it's supposed to be NFC, and I can't explain @russell.gallop 's claimed regression.
The only mostly-NFC change is I raised the stream type from raw_pwrite_stream to raw_ostream to help the unit tests (trivial as they are).

Can you revert that for now and just use raw_svector_ostream in the unittests? raw_svector_ostream implements raw_pwrite_stream, which should match the existing API. LGTM after that (though also wait if @russell.gallop has comments still).

@russell.gallop can you still repro a regression with the current patch?

llvm/include/llvm/Support/TimeProfiler.h

80

Why the extra include?

[mbs-modular]

• woops, BeginningOfTime must always capture now according to the system
• Russell's comments
• Missed two of Russell's comments
• Project even the default StringRef ctor
• Revert raw_pwrite_steram change to remove any uncertainty about perf regression.

[mbs-modular]

Thx again, reverted raw_pwrite_stream change, timings look like +3% with -ftime-trace as usual.

llvm/include/llvm/Support/TimeProfiler.h

80

Just a IWYU force of habit I guess.

[mbs-modular]

[support] Prepare TimeProfiler for cross-thread support

This NFC prepares the TimeProfiler to support the construction
and completion of time profiling 'entries' across threads.

• Add ClockType alias so we can change the clock in one place.
• (trivial) Use c++ usings instead of typedefs
• Rename Entry to TimeTraceProfilerEntry since this type will eventually become public.
• Add an intro comment.
• Add some smoke unit tests.

[russell.gallop]

@russell.gallop can you still repro a regression with the current patch?

Sorry to take a while to reply.

I rebuilt with Diff 460060 applied to 40ab7875f8ccb8d1b0166bf91475fc4d662cffe9 and yes, I do still see a build performance impact with -ftime-trace. I reproduced this building SemaExpr.cpp from a stage2 build so this should be something that you can reproduce.

In spite of the warning about statistical outliers (it was a pretty quiet PC), there is no overlap between the range of times with and without -ftime-trace so it's not just one or two samples causing this.

f:\git\llvm-project\stage2>%USERPROFILE%\bin\hyperfine -w 1 -m 10 "F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp" "F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace"
Benchmark #1: F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp
  Time (mean ± σ):     42.646 s ±  0.417 s    [User: 1.3 ms, System: 13.0 ms]
  Range (min … max):   41.783 s … 43.535 s    10 runs

  Warning: Statistical outliers were detected. Consider re-running this benchmark on a quiet PC without any interferences from other programs. It might help to use the '--warmup' or '--prepare' options.

Benchmark #2: F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace
  Time (mean ± σ):     46.308 s ±  1.108 s    [User: 3.9 ms, System: 9.9 ms]
  Range (min … max):   44.930 s … 49.074 s    10 runs

Summary
  'F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp' ran
    1.09 ± 0.03 times faster than 'F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace'

And without this patch it's just 1%.

f:\git\llvm-project\stage2>%USERPROFILE%\bin\hyperfine -w 1 -m 10 "F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp" "F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace"
Benchmark #1: F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp
  Time (mean ± σ):     40.761 s ±  1.346 s    [User: 1.2 ms, System: 7.4 ms]
  Range (min … max):   38.188 s … 42.256 s    10 runs

Benchmark #2: F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace
  Time (mean ± σ):     41.162 s ±  0.319 s    [User: 2.5 ms, System: 8.7 ms]
  Range (min … max):   40.750 s … 41.845 s    10 runs

Summary
  'F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp' ran
    1.01 ± 0.03 times faster than 'F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace'

Sorry I don't have time to look into this in more depth, but it is a cause for concern that we might be losing a nice property of -ftime-trace.

Apart from this I'm happy with the patch.

(And many apologies in advance if it's something I'm doing wrong here! I'd be interested if anyone else can reproduce this on SemaExpr. If it's just me then I'd suggest not blocking this patch landing due to this.)

compiler-rt/test/fuzzer/cross_over.test

1 ↗

(On Diff #459923)

This doesn't look related to me.

compiler-rt/test/fuzzer/merge-control-file.test

1 ↗

(On Diff #459923)

This doesn't look related to me.

[jloser]

In D133153#3792269, @russell.gallop wrote:

@russell.gallop can you still repro a regression with the current patch?

Sorry to take a while to reply.

I rebuilt with Diff 460060 applied to 40ab7875f8ccb8d1b0166bf91475fc4d662cffe9 and yes, I do still see a build performance impact with -ftime-trace. I reproduced this building SemaExpr.cpp from a stage2 build so this should be something that you can reproduce.

In spite of the warning about statistical outliers (it was a pretty quiet PC), there is no overlap between the range of times with and without -ftime-trace so it's not just one or two samples causing this.

f:\git\llvm-project\stage2>%USERPROFILE%\bin\hyperfine -w 1 -m 10 "F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp" "F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace"
Benchmark #1: F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp
  Time (mean ± σ):     42.646 s ±  0.417 s    [User: 1.3 ms, System: 13.0 ms]
  Range (min … max):   41.783 s … 43.535 s    10 runs

  Warning: Statistical outliers were detected. Consider re-running this benchmark on a quiet PC without any interferences from other programs. It might help to use the '--warmup' or '--prepare' options.

Benchmark #2: F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace
  Time (mean ± σ):     46.308 s ±  1.108 s    [User: 3.9 ms, System: 9.9 ms]
  Range (min … max):   44.930 s … 49.074 s    10 runs

Summary
  'F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp' ran
    1.09 ± 0.03 times faster than 'F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace'

And without this patch it's just 1%.

f:\git\llvm-project\stage2>%USERPROFILE%\bin\hyperfine -w 1 -m 10 "F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp" "F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace"
Benchmark #1: F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp
  Time (mean ± σ):     40.761 s ±  1.346 s    [User: 1.2 ms, System: 7.4 ms]
  Range (min … max):   38.188 s … 42.256 s    10 runs

Benchmark #2: F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace
  Time (mean ± σ):     41.162 s ±  0.319 s    [User: 2.5 ms, System: 8.7 ms]
  Range (min … max):   40.750 s … 41.845 s    10 runs

Summary
  'F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp' ran
    1.01 ± 0.03 times faster than 'F:\git\llvm-project\stage1\bin\clang-cl.exe  /nologo -TP -DGTEST_HAS_RTTI=0 -DUNICODE -D_CRT_NONSTDC_NO_DEPRECATE -D_CRT_NONSTDC_NO_WARNINGS -D_CRT_SECURE_NO_DEPRECATE -D_CRT_SECURE_NO_WARNINGS -D_GNU_SOURCE -D_HAS_EXCEPTIONS=0 -D_SCL_SECURE_NO_DEPRECATE -D_SCL_SECURE_NO_WARNINGS -D_UNICODE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools\clang\lib\Sema -IF:\git\llvm-project\clang\lib\Sema -IF:\git\llvm-project\clang\include -Itools\clang\include -Iinclude -IF:\git\llvm-project\llvm\include -Wno-nonportable-include-path /Zc:inline /Zc:__cplusplus /Oi /Brepro /bigobj /permissive- /W4  -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported /Gw /MT /O2 /Ob2 /DNDEBUG    /EHs-c- /GR- -std:c++17 /Fotools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\SemaExpr.cpp.obj /Fdtools\clang\lib\Sema\CMakeFiles\obj.clangSema.dir\ -c F:\git\llvm-project\clang\lib\Sema\SemaExpr.cpp -ftime-trace'

Sorry I don't have time to look into this in more depth, but it is a cause for concern that we might be losing a nice property of -ftime-trace.

Apart from this I'm happy with the patch.

(And many apologies in advance if it's something I'm doing wrong here! I'd be interested if anyone else can reproduce this on SemaExpr. If it's just me then I'd suggest not blocking this patch landing due to this.)

@mbs-modular - it'd be interesting to see if this is something you can repro on Linux with a stage2 build.

Other than that, this patch LGTM. If you need me or someone else to commit this on your behalf, can you please provide the email address you'd like to use for commit attribution?

[mbs-modular]

git switch mbs/time_profiler_warmup
git rebase 40ab78
cmake -S llvm -B build -G Ninja -DLLVM_ENABLE_PROJECTS=clang -DLLVM_TARGETS_TO_BUILD=X86 -DCMAKE_BUILD_TYPE=Release -DLLVM_USE_LINKER=lld -DCMAKE_CXX_COMPILER=/usr/bin/clang++ -DCMAKE_C_COMPILER=/usr/bin/clang
cmake --build build
touch clang/lib/Sema/SemaExpr.cpp
cd build
ninja tools/clang/lib/Sema/CMakeFiles/obj.clangSema.dir/SemaExpr.cpp.o -v

> /usr/bin/clang++ -DGTEST_HAS_RTTI=0 -D_GNU_SOURCE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -I/home/mbs/github/mbs-llvm-project/build/tools/clang/lib/Sema -I/home/mbs/github/mbs-llvm-project/clang/lib/Sema -I/home/mbs/github/mbs-llvm-project/clang/include -I/home/mbs/github/mbs-llvm-project/build/tools/clang/include -I/home/mbs/github/mbs-llvm-project/build/include -I/home/mbs/github/mbs-llvm-project/llvm/include -fPIC -fno-semantic-interposition -fvisibility-inlines-hidden -Werror=date-time -Werror=unguarded-availability-new -Wall -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -pedantic -Wno-long-long -Wc++98-compat-extra-semi -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported -fdiagnostics-color -ffunction-sections -fdata-sections -fno-common -Woverloaded-virtual -Wno-nested-anon-types -O3 -DNDEBUG  -fno-exceptions -fno-rtti -std=c++17 -MD -MT tools/clang/lib/Sema/CMakeFiles/obj.clangSema.dir/SemaExpr.cpp.o -MF tools/clang/lib/Sema/CMakeFiles/obj.clangSema.dir/SemaExpr.cpp.o.d -o tools/clang/lib/Sema/CMakeFiles/obj.clangSema.dir/SemaExpr.cpp.o -c /home/mbs/github/mbs-llvm-project/clang/lib/Sema/SemaExpr.cpp

CLANG="/home/mbs/github/mbs-llvm-project/build/bin/clang++"
CMD="$CLANG -DGTEST_HAS_RTTI=0 -D_GNU_SOURCE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -I/home/mbs/github/mbs-llvm-project/build/tools/clang/lib/Sema -I/home/mbs/github/mbs-llvm-project/clang/lib/Sema -I/home/mbs/github/mbs-llvm-project/clang/include -I/home/mbs/github/mbs-llvm-project/build/tools/clang/include -I/home/mbs/github/mbs-llvm-project/build/include -I/home/mbs/github/mbs-llvm-project/llvm/include -fPIC -fno-semantic-interposition -fvisibility-inlines-hidden -Werror=date-time -Werror=unguarded-availability-new -Wall -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -pedantic -Wno-long-long -Wc++98-compat-extra-semi -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -Wctad-maybe-unsupported -fdiagnostics-color -ffunction-sections -fdata-sections -fno-common -Woverloaded-virtual -Wno-nested-anon-types -O3 -DNDEBUG  -fno-exceptions -fno-rtti -std=c++17 -MD -MT tools/clang/lib/Sema/CMakeFiles/obj.clangSema.dir/SemaExpr.cpp.o -MF tools/clang/lib/Sema/CMakeFiles/obj.clangSema.dir/SemaExpr.cpp.o.d -o tools/clang/lib/Sema/CMakeFiles/obj.clangSema.dir/SemaExpr.cpp.o -c /home/mbs/github/mbs-llvm-project/clang/lib/Sema/SemaExpr.cpp"

for i in {1..15}; do /usr/bin/time -f "%e" $CMD; done

> 23.93
23.86
24.12
23.84
23.81
23.71
23.74
23.86
23.74
23.74
23.72
23.80
23.65
23.75
23.74


for i in {1..15}; do /usr/bin/time -f "%e" $CMD -ftime-trace; done

> 25.19
25.17
25.08
25.17
25.09
25.18
24.97
25.10
24.93
24.80
24.71
25.04
25.06
25.47
25.38

cd ..
git switch main
git checkout 40ab78
cmake --build build
cd build

for i in {1..15}; do /usr/bin/time -f "%e" $CMD; done

> 24.11
23.96
23.89
23.88
23.80
23.82
23.90
23.90
23.96
23.83
23.86
23.84
23.92
23.85
23.68

for i in {1..15}; do /usr/bin/time -f "%e" $CMD -ftime-trace; done

> 25.18
25.27
25.27
25.25
25.64
25.48
25.12
25.07
25.32
25.14
25.27
25.14
25.30
25.22
25.16

Ratio of with flag to without flag is 1.06 both with and without patch.
Ratio of without patch to with path is 1.01 both with and without flag.
I confirmed I'm indeed using the clang with the changes by emitting error output.
Given the disagreement on your measured times with and without the patch even without the -ftime-trace flag I'm inclined to write this off to very non-gaussian sampling noise on your setup. wdyt?

[russell.gallop]

Given the disagreement on your measured times with and without the patch even without the -ftime-trace flag I'm inclined to write this off to very non-gaussian sampling noise on your setup. wdyt?

As you can't reproduce this I think that sounds okay. Thanks.

llvm/include/llvm/Support/TimeProfiler.h

 //===- llvm/Support/TimeProfiler.h - Hierarchical Time Profiler -*- 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
 //
 //===----------------------------------------------------------------------===//
+//
+// This provides lightweight and dependency-free machinery to trace execution
+// time around arbitrary code. Two API flavors are available.
+//
+// The primary API uses a RAII object to trigger tracing:
+//
+// \code
+//   {
+//     TimeTraceScope scope("my_event_name");
+//     ...my code...
+//   }
+// \endcode
+//
+// If the code to be profiled does not have a natural lexical scope then
+// it is also possible to start and end events with respect to an implicit
+// per-thread stack of profiling entries:
+//
+// \code
+//   timeTraceProfilerBegin("my_event_name");
+//   ...my code...
+//   timeTraceProfilerEnd();  // must be called on all control flow paths
+// \endcode
+//
+// Time profiling entries can be given an arbitrary name and, optionally,
+// an arbitrary 'detail' string. The resulting trace will include 'Total'
+// entries summing the time spent for each name. Thus, it's best to choose
+// names to be fairly generic, and rely on the detail field to capture
+// everything else of interest.
+//
+// To avoid lifetime issues name and detail strings are copied into the event
+// entries at their time of creation. Care should be taken to make string
+// construction cheap to prevent 'Heisenperf' effects. In particular, the
+// 'detail' argument may be a string-returning closure:
+//
+// \code
+//   int n;
+//   {
+//     TimeTraceScope scope("my_event_name",
+//                          [n]() { return (Twine("x=") + Twine(n)).str(); });
+//     ...my code...
+//   }
+// \endcode
+// The closure will not be called if tracing is disabled. Otherwise, the
+// resulting string will be directly moved into the entry.
+//
+// The main process should begin with a timeTraceProfilerInitialize, and
+// finish with timeTraceProfileWrite and timeTraceProfilerCleanup calls.
+// Each new thread should begin with a timeTraceProfilerInitialize, and
+// finish with a timeTraceProfilerFinishThread call.
+//
+// Timestamps come from std::chrono::stable_clock. Note that threads need
+// not see the same time from that clock, and the resolution may not be
+// the best available.
+//
+// Currently, there are a number of compatible viewers:
+//  - chrome://tracing is the original chromium trace viewer.
+//  - http://ui.perfetto.dev is the replacement for the above, under active
+//    development by Google as part of the 'Perfetto' project.
+//  - https://www.speedscope.app/ has also been reported as an option.
+//
+// Future work:
+//  - Support akin to LLVM_DEBUG for runtime enable/disable of named tracing
+//    families for non-debug builds which wish to support optional tracing.
+//  - Evaluate the detail closures at profile write time to avoid
+//    stringification costs interfering with tracing.
+//
+//===----------------------------------------------------------------------===//
 
 #ifndef LLVM_SUPPORT_TIMEPROFILER_H
 #define LLVM_SUPPORT_TIMEPROFILER_H
 
-#include "llvm/Support/Error.h"
 #include "llvm/ADT/STLFunctionalExtras.h"
+#include "llvm/ADT/StringRef.h"
+#include "llvm/Support/Error.h"
 
 namespace llvm {
 
 class raw_pwrite_stream;
 
 struct TimeTraceProfiler;
 TimeTraceProfiler *getTimeTraceProfilerInstance();
 

 /// Is the time trace profiler enabled, i.e. initialized?
 inline bool timeTraceProfilerEnabled() {
   return getTimeTraceProfilerInstance() != nullptr;
 }
 
 /// Write profiling data to output stream.
 /// Data produced is JSON, in Chrome "Trace Event" format, see
 /// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview
-void timeTraceProfilerWrite(raw_pwrite_stream &OS);
+void timeTraceProfilerWrite(raw_ostream &OS);
 
 /// Write profiling data to a file.
 /// The function will write to \p PreferredFileName if provided, if not
 /// then will write to \p FallbackFileName appending .time-trace.
 /// Returns a StringError indicating a failure if the function is
 /// unable to open the file for writing.
 Error timeTraceProfilerWrite(StringRef PreferredFileName,
                              StringRef FallbackFileName);

llvm/lib/Support/TimeProfiler.cpp

 #include "llvm/Support/Threading.h"
 #include <algorithm>
 #include <cassert>
 #include <chrono>
 #include <mutex>
 #include <string>
 #include <vector>
 
-using namespace std::chrono;
 using namespace llvm;
 
 namespace {
 
+using std::chrono::duration;
+using std::chrono::duration_cast;
+using std::chrono::microseconds;
+using std::chrono::steady_clock;
+using std::chrono::system_clock;
+using std::chrono::time_point;
+using std::chrono::time_point_cast;
+
 struct TimeTraceProfilerInstances {
   std::mutex Lock;
   std::vector<TimeTraceProfiler *> List;
 };
 
 TimeTraceProfilerInstances &getTimeTraceProfilerInstances() {
   static TimeTraceProfilerInstances Instances;
   return Instances;
 }
 
 } // anonymous namespace
 
 // Per Thread instance
 static LLVM_THREAD_LOCAL TimeTraceProfiler *TimeTraceProfilerInstance = nullptr;
 
 TimeTraceProfiler *llvm::getTimeTraceProfilerInstance() {
   return TimeTraceProfilerInstance;
 }
 
-typedef duration<steady_clock::rep, steady_clock::period> DurationType;
-typedef time_point<steady_clock> TimePointType;
-typedef std::pair<size_t, DurationType> CountAndDurationType;
-typedef std::pair<std::string, CountAndDurationType>
-    NameAndCountAndDurationType;
-
 namespace {
-struct Entry {
+
+using ClockType = steady_clock;
+using TimePointType = time_point<ClockType>;
+using DurationType = duration<ClockType::rep, ClockType::period>;
+using CountAndDurationType = std::pair<size_t, DurationType>;
+using NameAndCountAndDurationType =
+    std::pair<std::string, CountAndDurationType>;
+
+/// Represents an open or completed time section entry to be captured.
+struct TimeTraceProfilerEntry {
   const TimePointType Start;
   TimePointType End;
   const std::string Name;
   const std::string Detail;
 
-  Entry(TimePointType &&S, TimePointType &&E, std::string &&N, std::string &&Dt)
+  TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
+                         std::string &&Dt)
       : Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
         Detail(std::move(Dt)) {}
 
   // Calculate timings for FlameGraph. Cast time points to microsecond precision
-  // rather than casting duration. This avoid truncation issues causing inner
+  // rather than casting duration. This avoids truncation issues causing inner
   // scopes overruning outer scopes.
-  steady_clock::rep getFlameGraphStartUs(TimePointType StartTime) const {
+  ClockType::rep getFlameGraphStartUs(TimePointType StartTime) const {
     return (time_point_cast<microseconds>(Start) -
             time_point_cast<microseconds>(StartTime))
         .count();
   }
 
-  steady_clock::rep getFlameGraphDurUs() const {
+  ClockType::rep getFlameGraphDurUs() const {
     return (time_point_cast<microseconds>(End) -
             time_point_cast<microseconds>(Start))
         .count();
   }
 };
-} // namespace
+
+} // anonymous namespace
 
 struct llvm::TimeTraceProfiler {
   TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "")
-      : BeginningOfTime(system_clock::now()), StartTime(steady_clock::now()),
+      : BeginningOfTime(system_clock::now()), StartTime(ClockType::now()),
         ProcName(ProcName), Pid(sys::Process::getProcessId()),
         Tid(llvm::get_threadid()), TimeTraceGranularity(TimeTraceGranularity) {
     llvm::get_thread_name(ThreadName);
   }
 
   void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
-    Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name),
+    Stack.emplace_back(ClockType::now(), TimePointType(), std::move(Name),
                        Detail());
   }
 
   void end() {
     assert(!Stack.empty() && "Must call begin() first");
-    Entry &E = Stack.back();
-    E.End = steady_clock::now();
+    TimeTraceProfilerEntry &E = Stack.back();
+    E.End = ClockType::now();
 
     // Check that end times monotonically increase.
     assert((Entries.empty() ||
             (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >=
              Entries.back().getFlameGraphStartUs(StartTime) +
                  Entries.back().getFlameGraphDurUs())) &&
            "TimeProfiler scope ended earlier than previous scope");
 
     // Calculate duration at full precision for overall counts.
     DurationType Duration = E.End - E.Start;
 
     // Only include sections longer or equal to TimeTraceGranularity msec.
     if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity)
       Entries.emplace_back(E);
 
     // Track total time taken by each "name", but only the topmost levels of
     // them; e.g. if there's a template instantiation that instantiates other
     // templates from within, we only want to add the topmost one. "topmost"
     // happens to be the ones that don't have any currently open entries above
     // itself.
     if (llvm::none_of(llvm::drop_begin(llvm::reverse(Stack)),
-                      [&](const Entry &Val) { return Val.Name == E.Name; })) {
+                      [&](const TimeTraceProfilerEntry &Val) {
+                        return Val.Name == E.Name;
+                      })) {
       auto &CountAndTotal = CountAndTotalPerName[E.Name];
       CountAndTotal.first++;
       CountAndTotal.second += Duration;
     }
 
     Stack.pop_back();
   }
 
   // Write events from this TimeTraceProfilerInstance and
   // ThreadTimeTraceProfilerInstances.
-  void write(raw_pwrite_stream &OS) {
+  void write(raw_ostream &OS) {
     // Acquire Mutex as reading ThreadTimeTraceProfilerInstances.
     auto &Instances = getTimeTraceProfilerInstances();
     std::lock_guard<std::mutex> Lock(Instances.Lock);
     assert(Stack.empty() &&
            "All profiler sections should be ended when calling write");
     assert(llvm::all_of(Instances.List,
                         [](const auto &TTP) { return TTP->Stack.empty(); }) &&
            "All profiler sections should be ended when calling write");
auto writeEvent = [&](const auto &E, uint64_t Tid) {
         J.attribute("ts", StartUs);
         J.attribute("dur", DurUs);
         J.attribute("name", E.Name);
         if (!E.Detail.empty()) {
           J.attributeObject("args", [&] { J.attribute("detail", E.Detail); });
         }
       });
     };
-    for (const Entry &E : Entries)
+    for (const TimeTraceProfilerEntry &E : Entries)
       writeEvent(E, this->Tid);
     for (const TimeTraceProfiler *TTP : Instances.List)
-      for (const Entry &E : TTP->Entries)
+      for (const TimeTraceProfilerEntry &E : TTP->Entries)
         writeEvent(E, TTP->Tid);
 
     // Emit totals by section name as additional "thread" events, sorted from
     // longest one.
     // Find highest used thread id.
     uint64_t MaxTid = this->Tid;
     for (const TimeTraceProfiler *TTP : Instances.List)
       MaxTid = std::max(MaxTid, TTP->Tid);
void write(raw_ostream &OS) {
     J.attribute("beginningOfTime",
                 time_point_cast<microseconds>(BeginningOfTime)
                     .time_since_epoch()
                     .count());
 
     J.objectEnd();
   }
 
-  SmallVector<Entry, 16> Stack;
-  SmallVector<Entry, 128> Entries;
+  SmallVector<TimeTraceProfilerEntry, 16> Stack;
+  SmallVector<TimeTraceProfilerEntry, 128> Entries;
   StringMap<CountAndDurationType> CountAndTotalPerName;
+  // System clock time when the session was begun.
   const time_point<system_clock> BeginningOfTime;
+  // Profiling clock time when the session was begun.
   const TimePointType StartTime;
   const std::string ProcName;
   const sys::Process::Pid Pid;
   SmallString<0> ThreadName;
   const uint64_t Tid;
 
   // Minimum time granularity (in microseconds)
   const unsigned TimeTraceGranularity;

 // This doesn't remove the instance, just moves the pointer to global vector.
 void llvm::timeTraceProfilerFinishThread() {
   auto &Instances = getTimeTraceProfilerInstances();
   std::lock_guard<std::mutex> Lock(Instances.Lock);
   Instances.List.push_back(TimeTraceProfilerInstance);
   TimeTraceProfilerInstance = nullptr;
 }
 
-void llvm::timeTraceProfilerWrite(raw_pwrite_stream &OS) {
+void llvm::timeTraceProfilerWrite(raw_ostream &OS) {
   assert(TimeTraceProfilerInstance != nullptr &&
          "Profiler object can't be null");
   TimeTraceProfilerInstance->write(OS);
 }
 
 Error llvm::timeTraceProfilerWrite(StringRef PreferredFileName,
                                    StringRef FallbackFileName) {
   assert(TimeTraceProfilerInstance != nullptr &&

llvm/unittests/Support/CMakeLists.txt

add_llvm_unittest(SupportTests
   SymbolRemappingReaderTest.cpp
   TarWriterTest.cpp
   TargetParserTest.cpp
   TaskQueueTest.cpp
   ThreadLocalTest.cpp
   ThreadPool.cpp
   Threading.cpp
   TimerTest.cpp
+  TimeProfilerTest.cpp
   ToolOutputFileTest.cpp
   TypeNameTest.cpp
   TypeTraitsTest.cpp
   TrailingObjectsTest.cpp
   TrigramIndexTest.cpp
   UnicodeTest.cpp
   VersionTupleTest.cpp
   VirtualFileSystemTest.cpp

llvm/unittests/Support/TimeProfilerTest.cpp

+//===- unittests/TimeProfilerTest.cpp - TimeProfiler tests ----------------===//
+//
+// 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
+//
+//===----------------------------------------------------------------------===//
+// These are bare-minimum 'smoke' tests of the time profiler. Not tested:
+//  - multi-threading
+//  - 'Total' entries
+//  - elision of short or ill-formed entries
+//  - detail callback
+//  - no calls to now() if profiling is disabled
+//  - suppression of contributions to total entries for nested entries
+//===----------------------------------------------------------------------===//
+
+#include "llvm/Support/TimeProfiler.h"
+#include "gtest/gtest.h"
+
+using namespace llvm;
+
+namespace {
+
+void setupProfiler() {
+  timeTraceProfilerInitialize(/*TimeTraceGranularity=*/0, "test");
+}
+
+std::string teardownProfiler() {
+  std::string json;
+  raw_string_ostream os(json);
+  timeTraceProfilerWrite(os);
+  timeTraceProfilerCleanup();
+  return json;
+}
+
+TEST(TimeProfiler, Scope_Smoke) {
+  setupProfiler();
+
+  { TimeTraceScope scope("event", "detail"); }
+
+  std::string json = teardownProfiler();
+  ASSERT_TRUE(json.find(R"("name":"event")") != std::string::npos);
+  ASSERT_TRUE(json.find(R"("detail":"detail")") != std::string::npos);
+}
+
+TEST(TimeProfiler, Begin_End_Smoke) {
+  setupProfiler();
+
+  timeTraceProfilerBegin("event", "detail");
+  timeTraceProfilerEnd();
+
+  std::string json = teardownProfiler();
+  ASSERT_TRUE(json.find(R"("name":"event")") != std::string::npos);
+  ASSERT_TRUE(json.find(R"("detail":"detail")") != std::string::npos);
+}
+
+TEST(TimeProfiler, Begin_End_Disabled) {
+  // Nothing should be observable here. The test is really just making sure
+  // we've not got a stray nullptr deref.
+  timeTraceProfilerBegin("event", "detail");
+  timeTraceProfilerEnd();
+}
+
+} // namespace