commit 99c93e604e06d712d33a43e62e0e871f08b3c1c8
author Ghanan Gowripalan <ghanan@google.com> Mon Mar 11 23:43:02 2024 +0000
committer CQ Bot <fuchsia-internal-scoped@luci-project-accounts.iam.gserviceaccount.com> Mon Mar 11 23:43:02 2024 +0000
tree ddf71e3b7ad4b90b47e9324b27549702752d2147
parent becf6117486599d8c798854de1b09b4830ebe096

[starnix] Don't log `/dev/null` writes by default

...and introduce a new build argument to enable INFO logging of
`/dev/null` writes named `starnix_log_dev_null_writes_at_info`.

commit adbc7e14533ca6a850dd22da80007d19f80219aa logged all writes to
`/dev/null` at the INFO level.

Some applications choose to unconditionally write some data to a file.
When such applications do not care about the data being written, or
simply want to throw away the data, they may write to `/dev/null`
instead of a regular file with the expectation that the "written" data
is thrown away with no side effects.

Since such applications do not expect to observe data written to
`/dev/null`, there is no need to log it in Starnix at the INFO level.

Developers who are interested in logs/data written to `/dev/null` should
set the (newly added) `starnix_log_dev_null_writes_at_info` build arg
to effectively revert this change locally.

Note that logging writes to `/dev/null` negatively implacted GFXBench's
test launch time. Dropping the logs altogether reduced the test launch
time by ~20.11% or ~5 mins - dropping from ~1303s to ~1041s.

This should also improve the initial/one-time copying of assets GFXBench
performs as that operation spews similar logs to `/dev/null` as what is
spewed during the actual test. That operation was not measured though.

* With /dev/null logs (Avg Init: 1303.33s; Avg Test: 64.33s)
```
** Init: 1325s; Test: 65s
[01474.859131][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>GLBNativeLog(2902:3168) Init test: vulkan_5_normal_off
[02799.440015][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(2902:3168) loaded: vulkan_5_normal_off
[02799.440080][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(2902:3168) running vulkan_5_normal_off
[02864.047363][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(2902:3168)    "result_id": "vulkan_5_normal_off",
[02864.047455][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(2902:3168)    "test_id": "vulkan_5_normal_off",
[02864.047613][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(2902:3168)  "test_id": "vulkan_5_normal_off"
[02864.051787][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(2902:3168) finished: vulkan_5_normal_off

** Init: 1293s; Test: 64s
[03095.799034][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>GLBNativeLog(2902:3231) Init test: vulkan_5_normal_off
[04388.215880][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(2902:3231) loaded: vulkan_5_normal_off
[04388.215920][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(2902:3231) running vulkan_5_normal_off
[04452.851054][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(2902:3231)    "result_id": "vulkan_5_normal_off",
[04452.851152][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(2902:3231)    "test_id": "vulkan_5_normal_off",
[04452.851310][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(2902:3231)  "test_id": "vulkan_5_normal_off"
[04452.851426][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(2902:3231) finished: vulkan_5_normal_off

** Init: 1292s; Test: 64s
[04474.280065][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>GLBNativeLog(2902:3289) Init test: vulkan_5_normal_off
[05766.004659][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(2902:3289) loaded: vulkan_5_normal_off
[05766.004719][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(2902:3289) running vulkan_5_normal_off
[05830.611350][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(2902:3289)    "result_id": "vulkan_5_normal_off",
[05830.611398][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(2902:3289)    "test_id": "vulkan_5_normal_off",
[05830.611477][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(2902:3289)  "test_id": "vulkan_5_normal_off"
[05830.611853][kernels:MSNRay8][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(2902:3289) finished: vulkan_5_normal_off
```

* Without /dev/null logs (Avg Init: 1041.33s; Avg Test: 64.67s)
```
** Init: 1013s; Test: 65s
[01085.131487][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>GLBNativeLog(3666:3877) Init test: vulkan_5_normal_off
[02098.466473][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(3666:3877) loaded: vulkan_5_normal_off
[02098.466531][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(3666:3877) running vulkan_5_normal_off
[02163.080822][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(3666:3877)    "result_id": "vulkan_5_normal_off",
[02163.080878][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(3666:3877)    "test_id": "vulkan_5_normal_off",
[02163.080963][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(3666:3877)  "test_id": "vulkan_5_normal_off"
[02163.081038][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(3666:3877) finished: vulkan_5_normal_off

** Init: 1061s; Test: 65s
[02452.373327][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>GLBNativeLog(3666:3975) Init test: vulkan_5_normal_off
[03513.994437][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(3666:3975) loaded: vulkan_5_normal_off
[03513.994461][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(3666:3975) running vulkan_5_normal_off
[03578.686778][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(3666:3975)    "result_id": "vulkan_5_normal_off",
[03578.686828][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(3666:3975)    "test_id": "vulkan_5_normal_off",
[03578.686912][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(3666:3975)  "test_id": "vulkan_5_normal_off"
[03578.687084][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(3666:3975) finished: vulkan_5_normal_off

** Init: 1050s; Test: 64s
[03610.433413][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>GLBNativeLog(3666:4010) Init test: vulkan_5_normal_off
[04660.050963][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(3666:4010) loaded: vulkan_5_normal_off
[04660.051004][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(3666:4010) running vulkan_5_normal_off
[04724.689243][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(3666:4010)    "result_id": "vulkan_5_normal_off",
[04724.689296][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(3666:4010)    "test_id": "vulkan_5_normal_off",
[04724.689380][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>_logcat_(3666:4010)  "test_id": "vulkan_5_normal_off"
[04724.697189][kernels:uC5Fqh6][43:43[fxlogcat],kmsg,starnix] INFO: <6>  Runner(3666:4010) finished: vulkan_5_normal_off
```

Bug: b/324955805
Change-Id: I933c6ce6d389b3ca4e6c17c9978bdd6fbb5e3d22
Reviewed-on: https://fuchsia-review.googlesource.com/c/fuchsia/+/1004902
Fuchsia-Auto-Submit: Ghanan Gowripalan <ghanan@google.com>
Reviewed-by: Theodore Dubois <tbodt@google.com>
Reviewed-by: Adam Perry <adamperry@google.com>
Commit-Queue: Ghanan Gowripalan <ghanan@google.com>
Reviewed-by: Adam Barth <abarth@google.com>