site/en/advanced/performance/json-trace-profile.md - bazel - Git at Google

 Project: /_project.yaml
 Book: /_book.yaml

 # JSON Trace Profile

 {% include "_buttons.html" %}

 The JSON trace profile can be very useful to quickly understand what Bazel spent
 time on during the invocation.

 By default, for all build-like commands and query, Bazel writes a profile into
 the output base named `command-$INOVCATION_ID.profile.gz`, where
 `$INOVCATION_ID` is the invocation identifier of the command. Bazel also creates
 a symlink called `command.profile.gz` in the output base that points the profile
 of the latest command. You can configure whether a profile is written with the
 [`--generate_json_trace_profile`](/reference/command-line-reference#flag--generate_json_trace_profile)
 flag, and the location it is written to with the
 [`--profile`](/docs/user-manual#profile) flag. Locations ending with `.gz` are
 compressed with GZIP. Bazel keeps the last 5 profiles, configurable by
 [`--profiles_to_retain`](/reference/command-line-reference#flag--generate_json_trace_profile),
 in the output base by default for post-build analysis. Explicitly passing a
 profile path with `--profile` disables automatic garbage collection.

 ## Tools

 You can load this profile into `chrome://tracing` or analyze and
 post-process it with other tools.

 ### `chrome://tracing`

 To visualize the profile, open `chrome://tracing` in a Chrome browser tab,
 click "Load" and pick the (potentially compressed) profile file. For more
 detailed results, click the boxes in the lower left corner.

 Example profile:

 ![Example profile](/docs/images/json-trace-profile.png "Example profile")

 **Figure 1.** Example profile.

 You can use these keyboard controls to navigate:

 *   Press `1` for "select" mode. In this mode, you can select
     particular boxes to inspect the event details (see lower left corner).
     Select multiple events to get a summary and aggregated statistics.
 *   Press `2` for "pan" mode. Then drag the mouse to move the view. You
     can also use `a`/`d` to move left/right.
 *   Press `3` for "zoom" mode. Then drag the mouse to zoom. You can
     also use `w`/`s` to zoom in/out.
 *   Press `4` for "timing" mode where you can measure the distance
     between two events.
 *   Press `?` to learn about all controls.

 ### `bazel analyze-profile`

 The Bazel subcommand [`analyze-profile`](/docs/user-manual#analyze-profile)
 consumes a profile format and prints cumulative statistics for
 different task types for each build phase and an analysis of the critical path.

 For example, the commands

 ```
 $ bazel build --profile=/tmp/profile.gz //path/to:target
 ...
 $ bazel analyze-profile /tmp/profile.gz
 ```

 may yield output of this form:

 ```
 INFO: Profile created on Tue Jun 16 08:59:40 CEST 2020, build ID: 0589419c-738b-4676-a374-18f7bbc7ac23, output base: /home/johndoe/.cache/bazel/_bazel_johndoe/d8eb7a85967b22409442664d380222c0

 === PHASE SUMMARY INFORMATION ===

 Total launch phase time         1.070 s   12.95%
 Total init phase time           0.299 s    3.62%
 Total loading phase time        0.878 s   10.64%
 Total analysis phase time       1.319 s   15.98%
 Total preparation phase time    0.047 s    0.57%
 Total execution phase time      4.629 s   56.05%
 Total finish phase time         0.014 s    0.18%
 ------------------------------------------------
 Total run time                  8.260 s  100.00%

 Critical path (4.245 s):
        Time Percentage   Description
     8.85 ms    0.21%   _Ccompiler_Udeps for @local_config_cc// compiler_deps
     3.839 s   90.44%   action 'Compiling external/com_google_protobuf/src/google/protobuf/compiler/php/php_generator.cc [for host]'
      270 ms    6.36%   action 'Linking external/com_google_protobuf/protoc [for host]'
     0.25 ms    0.01%   runfiles for @com_google_protobuf// protoc
      126 ms    2.97%   action 'ProtoCompile external/com_google_protobuf/python/google/protobuf/compiler/plugin_pb2.py'
     0.96 ms    0.02%   runfiles for //tools/aquery_differ aquery_differ
 ```

 ### Bazel Invocation Analyzer

 The open-source
 [Bazel Invocation Analyzer](https://github.com/EngFlow/bazel_invocation_analyzer){: .external}
 consumes a profile format and prints suggestions on how to improve
 the build’s performance. This analysis can be performed using its CLI or on
 [https://analyzer.engflow.com](https://analyzer.engflow.com){: .external}.

 ### `jq`

 `jq` is like `sed` for JSON data. An example usage of `jq` to extract all
 durations of the sandbox creation step in local action execution:

 ```
 $ zcat $(../bazel-6.0.0rc1-linux-x86_64 info output_base)/command.profile.gz | jq '.traceEvents | .[] | select(.name == "sandbox.createFileSystem") | .dur'
 6378
 7247
 11850
 13756
 6555
 7445
 8487
 15520
 [...]
 ```

 ## Profile information {:#profile-information}

 The profile contains multiple rows. Usually the bulk of rows represent Bazel
 threads and their corresponding events, but some special rows are also included.

 The special rows included depend on the version of Bazel invoked when the
 profile was created, and may be customized by different flags.

 Figure 1 shows a profile created with Bazel v5.3.1 and includes these rows:

 *   `action count`: Displays how many concurrent actions were in flight. Click
     on it to see the actual value. Should go up to the value of
     [`--jobs`](/reference/command-line-reference#flag--jobs) in clean
     builds.
 *   `CPU usage (Bazel)`: For each second of the build, displays the amount of
     CPU that was used by Bazel (a value of 1 equals one core being 100% busy).
 *   `Critical Path`: Displays one block for each action on the critical path.
 *   `Main Thread`: Bazel’s main thread. Useful to get a high-level picture of
     what Bazel is doing, for example "Launch Blaze", "evaluateTargetPatterns",
     and "runAnalysisPhase".
 *   `Garbage Collector`: Displays minor and major Garbage Collection (GC)
     pauses.

 ## Common performance issues {:#common-performance-issues}

 When analyzing performance profiles, look for:

 *   Slower than expected analysis phase (`runAnalysisPhase`), especially on
     incremental builds. This can be a sign of a poor rule implementation, for
     example one that flattens depsets. Package loading can be slow by an
     excessive amount of targets, complex macros or recursive globs.
 *   Individual slow actions, especially those on the critical path. It might be
     possible to split large actions into multiple smaller actions or reduce the
     set of (transitive) dependencies to speed them up. Also check for an unusual
     high non-`PROCESS_TIME` (such as `REMOTE_SETUP` or `FETCH`).
 *   Bottlenecks, that is a small number of threads is busy while all others are
     idling / waiting for the result (see around 22s and 29s in Figure 1).
     Optimizing this will most likely require touching the rule implementations
     or Bazel itself to introduce more parallelism. This can also happen when
     there is an unusual amount of GC.

 ## Profile file format {:#profile-file-format}

 The top-level object contains metadata (`otherData`) and the actual tracing data
 (`traceEvents`). The metadata contains extra info, for example the invocation ID
 and date of the Bazel invocation.

 Example:

 ```json
 {
   "otherData": {
     "build_id": "101bff9a-7243-4c1a-8503-9dc6ae4c3b05",
     "date": "Wed Oct 26 08:22:35 CEST 2022",
     "profile_finish_ts": "1677666095162000",
     "output_base": "/usr/local/google/_bazel_johndoe/573d4be77eaa72b91a3dfaa497bf8cd0"
   },
   "traceEvents": [
     {"name":"thread_name","ph":"M","pid":1,"tid":0,"args":{"name":"Critical Path"}},
     ...
     {"cat":"build phase marker","name":"Launch Blaze","ph":"X","ts":-1306000,"dur":1306000,"pid":1,"tid":21},
     ...
     {"cat":"package creation","name":"foo","ph":"X","ts":2685358,"dur":784,"pid":1,"tid":246},
     ...
     {"name":"thread_name","ph":"M","pid":1,"tid":11,"args":{"name":"Garbage Collector"}},
     {"cat":"gc notification","name":"minor GC","ph":"X","ts":825986,"dur":11000,"pid":1,"tid":11},
     ...
     {"cat":"action processing","name":"Compiling foo/bar.c","ph":"X","ts":54413389,"dur":357594,"pid":1,"args":{"mnemonic":"CppCompile"},"tid":341},
  ]
 }
 ```

 Timestamps (`ts`) and durations (`dur`) in the trace events are given in
 microseconds. The category (`cat`) is one of enum values of `ProfilerTask`.
 Note that some events are merged together if they are very short and close to
 each other; pass
 [`--noslim_profile`](/reference/command-line-reference#flag--slim_profile)
 if you would like to prevent event merging.

 See also the
 [Chrome Trace Event Format Specification](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview){: .external}.
	Project: /_project.yaml
	Book: /_book.yaml

	# JSON Trace Profile

	{% include "_buttons.html" %}

	The JSON trace profile can be very useful to quickly understand what Bazel spent
	time on during the invocation.

	By default, for all build-like commands and query, Bazel writes a profile into
	the output base named `command-$INOVCATION_ID.profile.gz`, where
	`$INOVCATION_ID` is the invocation identifier of the command. Bazel also creates
	a symlink called `command.profile.gz` in the output base that points the profile
	of the latest command. You can configure whether a profile is written with the
	[`--generate_json_trace_profile`](/reference/command-line-reference#flag--generate_json_trace_profile)
	flag, and the location it is written to with the
	[`--profile`](/docs/user-manual#profile) flag. Locations ending with `.gz` are
	compressed with GZIP. Bazel keeps the last 5 profiles, configurable by
	[`--profiles_to_retain`](/reference/command-line-reference#flag--generate_json_trace_profile),
	in the output base by default for post-build analysis. Explicitly passing a
	profile path with `--profile` disables automatic garbage collection.

	## Tools

	You can load this profile into `chrome://tracing` or analyze and
	post-process it with other tools.

	### `chrome://tracing`

	To visualize the profile, open `chrome://tracing` in a Chrome browser tab,
	click "Load" and pick the (potentially compressed) profile file. For more
	detailed results, click the boxes in the lower left corner.

	Example profile:

	![Example profile](/docs/images/json-trace-profile.png "Example profile")

	Figure 1. Example profile.

	You can use these keyboard controls to navigate:

	* Press `1` for "select" mode. In this mode, you can select
	particular boxes to inspect the event details (see lower left corner).
	Select multiple events to get a summary and aggregated statistics.
	* Press `2` for "pan" mode. Then drag the mouse to move the view. You
	can also use `a`/`d` to move left/right.
	* Press `3` for "zoom" mode. Then drag the mouse to zoom. You can
	also use `w`/`s` to zoom in/out.
	* Press `4` for "timing" mode where you can measure the distance
	between two events.
	* Press `?` to learn about all controls.

	### `bazel analyze-profile`

	The Bazel subcommand [`analyze-profile`](/docs/user-manual#analyze-profile)
	consumes a profile format and prints cumulative statistics for
	different task types for each build phase and an analysis of the critical path.

	For example, the commands

	```
	$ bazel build --profile=/tmp/profile.gz //path/to:target
	...
	$ bazel analyze-profile /tmp/profile.gz
	```

	may yield output of this form:

	```
	INFO: Profile created on Tue Jun 16 08:59:40 CEST 2020, build ID: 0589419c-738b-4676-a374-18f7bbc7ac23, output base: /home/johndoe/.cache/bazel/_bazel_johndoe/d8eb7a85967b22409442664d380222c0

	=== PHASE SUMMARY INFORMATION ===

	Total launch phase time 1.070 s 12.95%
	Total init phase time 0.299 s 3.62%
	Total loading phase time 0.878 s 10.64%
	Total analysis phase time 1.319 s 15.98%
	Total preparation phase time 0.047 s 0.57%
	Total execution phase time 4.629 s 56.05%
	Total finish phase time 0.014 s 0.18%
	------------------------------------------------
	Total run time 8.260 s 100.00%

	Critical path (4.245 s):
	Time Percentage Description
	8.85 ms 0.21% _Ccompiler_Udeps for @local_config_cc// compiler_deps
	3.839 s 90.44% action 'Compiling external/com_google_protobuf/src/google/protobuf/compiler/php/php_generator.cc [for host]'
	270 ms 6.36% action 'Linking external/com_google_protobuf/protoc [for host]'
	0.25 ms 0.01% runfiles for @com_google_protobuf// protoc
	126 ms 2.97% action 'ProtoCompile external/com_google_protobuf/python/google/protobuf/compiler/plugin_pb2.py'
	0.96 ms 0.02% runfiles for //tools/aquery_differ aquery_differ
	```

	### Bazel Invocation Analyzer

	The open-source
	[Bazel Invocation Analyzer](https://github.com/EngFlow/bazel_invocation_analyzer){: .external}
	consumes a profile format and prints suggestions on how to improve
	the build’s performance. This analysis can be performed using its CLI or on
	[https://analyzer.engflow.com](https://analyzer.engflow.com){: .external}.

	### `jq`

	`jq` is like `sed` for JSON data. An example usage of `jq` to extract all
	durations of the sandbox creation step in local action execution:

	```
	$ zcat $(../bazel-6.0.0rc1-linux-x86_64 info output_base)/command.profile.gz \| jq '.traceEvents \| .[] \| select(.name == "sandbox.createFileSystem") \| .dur'
	6378
	7247
	11850
	13756
	6555
	7445
	8487
	15520
	[...]
	```

	## Profile information {:#profile-information}

	The profile contains multiple rows. Usually the bulk of rows represent Bazel
	threads and their corresponding events, but some special rows are also included.

	The special rows included depend on the version of Bazel invoked when the
	profile was created, and may be customized by different flags.

	Figure 1 shows a profile created with Bazel v5.3.1 and includes these rows:

	* `action count`: Displays how many concurrent actions were in flight. Click
	on it to see the actual value. Should go up to the value of
	[`--jobs`](/reference/command-line-reference#flag--jobs) in clean
	builds.
	* `CPU usage (Bazel)`: For each second of the build, displays the amount of
	CPU that was used by Bazel (a value of 1 equals one core being 100% busy).
	* `Critical Path`: Displays one block for each action on the critical path.
	* `Main Thread`: Bazel’s main thread. Useful to get a high-level picture of
	what Bazel is doing, for example "Launch Blaze", "evaluateTargetPatterns",
	and "runAnalysisPhase".
	* `Garbage Collector`: Displays minor and major Garbage Collection (GC)
	pauses.

	## Common performance issues {:#common-performance-issues}

	When analyzing performance profiles, look for:

	* Slower than expected analysis phase (`runAnalysisPhase`), especially on
	incremental builds. This can be a sign of a poor rule implementation, for
	example one that flattens depsets. Package loading can be slow by an
	excessive amount of targets, complex macros or recursive globs.
	* Individual slow actions, especially those on the critical path. It might be
	possible to split large actions into multiple smaller actions or reduce the
	set of (transitive) dependencies to speed them up. Also check for an unusual
	high non-`PROCESS_TIME` (such as `REMOTE_SETUP` or `FETCH`).
	* Bottlenecks, that is a small number of threads is busy while all others are
	idling / waiting for the result (see around 22s and 29s in Figure 1).
	Optimizing this will most likely require touching the rule implementations
	or Bazel itself to introduce more parallelism. This can also happen when
	there is an unusual amount of GC.

	## Profile file format {:#profile-file-format}

	The top-level object contains metadata (`otherData`) and the actual tracing data
	(`traceEvents`). The metadata contains extra info, for example the invocation ID
	and date of the Bazel invocation.

	Example:

	```json
	{
	"otherData": {
	"build_id": "101bff9a-7243-4c1a-8503-9dc6ae4c3b05",
	"date": "Wed Oct 26 08:22:35 CEST 2022",
	"profile_finish_ts": "1677666095162000",
	"output_base": "/usr/local/google/_bazel_johndoe/573d4be77eaa72b91a3dfaa497bf8cd0"
	},
	"traceEvents": [
	{"name":"thread_name","ph":"M","pid":1,"tid":0,"args":{"name":"Critical Path"}},
	...
	{"cat":"build phase marker","name":"Launch Blaze","ph":"X","ts":-1306000,"dur":1306000,"pid":1,"tid":21},
	...
	{"cat":"package creation","name":"foo","ph":"X","ts":2685358,"dur":784,"pid":1,"tid":246},
	...
	{"name":"thread_name","ph":"M","pid":1,"tid":11,"args":{"name":"Garbage Collector"}},
	{"cat":"gc notification","name":"minor GC","ph":"X","ts":825986,"dur":11000,"pid":1,"tid":11},
	...
	{"cat":"action processing","name":"Compiling foo/bar.c","ph":"X","ts":54413389,"dur":357594,"pid":1,"args":{"mnemonic":"CppCompile"},"tid":341},
	]
	}
	```

	Timestamps (`ts`) and durations (`dur`) in the trace events are given in
	microseconds. The category (`cat`) is one of enum values of `ProfilerTask`.
	Note that some events are merged together if they are very short and close to
	each other; pass
	[`--noslim_profile`](/reference/command-line-reference#flag--slim_profile)
	if you would like to prevent event merging.

	See also the
	[Chrome Trace Event Format Specification](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview){: .external}.