[Bug analyzer/109361] New: RFE: SARIF output could contain timing/profile information

[Bug analyzer/109361] New: RFE: SARIF output could contain timing/profile information

[dmalcolm at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=109361

            Bug ID: 109361
           Summary: RFE: SARIF output could contain timing/profile
                    information
           Product: gcc
           Version: 13.0
            Status: UNCONFIRMED
          Severity: normal
          Priority: P3
         Component: analyzer
          Assignee: dmalcolm at gcc dot gnu.org
          Reporter: dmalcolm at gcc dot gnu.org
  Target Milestone: ---

My integration tests for -fanalyzer don't yet track how long the analyzer takes
on the real-world cases.

It would be nice for the .sarif files generated by
-fdiagnostics-format=sarif-file to contain profiling or timing information.

[Bug analyzer/109361] RFE: SARIF output could contain timing/profile information

[dmalcolm at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=109361

--- Comment #1 from David Malcolm <dmalcolm at gcc dot gnu.org> ---
Some existing SARIF properties we could generate:

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
3.20.7 startTimeUtc property

An invocation object MAY contain a property named startTimeUtc whose value is a
string in the format specified in §3.9, specifying the UTC date and time at
which the invocation started.

3.20.8 endTimeUtc property

An invocation object MAY contain a property named endTimeUtc whose value is a
string in the format specified in §3.9, specifying the UTC date and time at
which the invocation ended.

3.38.12 executionTimeUtc property

A threadFlowLocation object MAY contain a property named executionTimeUtc whose
value is a string in the format specified in §3.9, specifying the UTC date and
time at which the thread of execution through the code reached this location.

3.48.2 firstDetectionTimeUtc property

A resultProvenance object MAY contain a property named firstDetectionTimeUtc
whose value is a string in the format specified in §3.9, specifying the UTC
date and time at which the result was first detected. It SHOULD specify the
start time of the run in which the result was first detected, as opposed to,
for example, the time within the run at which the result was actually
generated.

NOTE: Using the run’s start time makes it possible to group together results
that were first detected in the same run.
3.48.3 lastDetectionTimeUtc property

A resultProvenance object MAY contain a property named lastDetectionTimeUtc
whose value is a string in the format specified in §3.9, specifying the UTC
date and time at which the result was most recently detected. It SHOULD specify
the start time of the run in which the result was most recently detected, as
opposed to, for example, the time within the run at which the result was
actually generated.

NOTE: Using the run’s start time makes it possible to group together results
that were detected in the same run.

If lastDetectionTimeUtc is absent, its default value SHALL be determined as
follows:

1.     If run.invocations is present, and if the startTimeUtc property
(§3.20.7) is present on any of the invocation objects (§3.20) in that array,
then the default is the earliest of those times.

2.     Otherwise, there is no default.

3.58.8 timeUtc property

A notification object MAY contain a property named timeUtc whose value is a
string in the format specified §3.9, specifying the UTC date and time at which
the analysis tool generated the notification.

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

or perhaps we could use a property bag (e.g. to capture timevar information)

[Bug analyzer/109361] RFE: SARIF output could contain timing/profile information

[dmalcolm at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=109361

David Malcolm <dmalcolm at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Last reconfirmed|                            |2023-03-31
     Ever confirmed|0                           |1
             Status|UNCONFIRMED                 |ASSIGNED

--- Comment #2 from David Malcolm <dmalcolm at gcc dot gnu.org> ---
(In reply to David Malcolm from comment #0)
> My integration tests for -fanalyzer don't yet track how long the analyzer
> takes on the real-world cases.

Filed as
https://github.com/davidmalcolm/gcc-analyzer-integration-tests/issues/5

> It would be nice for the .sarif files generated by
> -fdiagnostics-format=sarif-file to contain profiling or timing information.

I'm testing an implementation of this, which puts the -ftime-report data into a
property bag of the "invocation" object.

[Bug analyzer/109361] RFE: SARIF output could contain timing/profile information

[dmalcolm at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=109361

--- Comment #3 from David Malcolm <dmalcolm at gcc dot gnu.org> ---
Created attachment 54804
  --> https://gcc.gnu.org/bugzilla/attachment.cgi?id=54804&action=edit
v1 of patch for this

This patch works, but it also enables the output on stderr, and I see
significant differences in output with this.  Hence I'm working on a v2 patch
that adds a separate command-line option for enabling this.

[Bug analyzer/109361] RFE: SARIF output could contain timing/profile information

[dmalcolm at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=109361

--- Comment #4 from David Malcolm <dmalcolm at gcc dot gnu.org> ---
1st patch posted for this (adding -fsarif-time-report):
  https://gcc.gnu.org/pipermail/gcc-patches/2023-April/615109.html

2nd patch:
  https://gcc.gnu.org/pipermail/gcc-patches/2023-July/625767.html

[Bug analyzer/109361] RFE: SARIF output could contain timing/profile information

[cvs-commit at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=109361

--- Comment #5 from CVS Commits <cvs-commit at gcc dot gnu.org> ---
The master branch has been updated by David Malcolm <dmalcolm@gcc.gnu.org>:

https://gcc.gnu.org/g:75d623946d4b6ea80a777b789b116d4b4a2298dc

commit r14-2881-g75d623946d4b6ea80a777b789b116d4b4a2298dc
Author: David Malcolm <dmalcolm@redhat.com>
Date:   Mon Jul 31 11:13:02 2023 -0400

    SARIF and -ftime-report's output [PR109361]

    This patch adds support for embeddding profiling information about the
    compiler itself into the SARIF output.

    Specifically, if SARIF diagnostic output is requested, via
    -fdiagnostics-format=sarif-file or -fdiagnostics-format=sarif-stderr,
    then any -ftime-report output is written in JSON form into the SARIF
    output, rather than to stderr.

    In earlier versions of this patch I extended -ftime-report so that
    *as well* as writing to stderr, it would embed the information in any
    SARIF output.  This turned out to be awkward to use, in that I found
    myself needing to get the data in JSON form without also having it
    emitted on stderr (which was fouling my build scripts).

    The timing information is written to the SARIF as a "gcc/timeReport"
    property within a property bag of the "invocation" object.

    Here's an example of the output:

      "invocations": [
          {
              "executionSuccessful": true,
              "toolExecutionNotifications": [],
              "properties": {
                  "gcc/timeReport": {
                      "timevars": [
                          {
                              "name": "phase setup",
                              "elapsed": {
                                  "user": 0.04,
                                  "sys": 0,
                                  "wall": 0.04,
                                  "ggc_mem": 1863472
                              }
                          },

                          [...snip...]

                          {
                              "name": "analyzer: processing worklist",
                              "elapsed": {
                                  "user": 0.06,
                                  "sys": 0,
                                  "wall": 0.06,
                                  "ggc_mem": 48
                              }
                          },
                          {
                              "name": "analyzer: emitting diagnostics",
                              "elapsed": {
                                  "user": 0.01,
                                  "sys": 0,
                                  "wall": 0.01,
                                  "ggc_mem": 0
                              }
                          },
                          {
                              "name": "TOTAL",
                              "elapsed": {
                                  "user": 0.21,
                                  "sys": 0.03,
                                  "wall": 0.24,
                                  "ggc_mem": 3368736
                              }
                          }
                      ],
                      "CHECKING_P": true,
                      "flag_checking": true
                  }
              }
          }
      ]

    The documentation notes that the precise output format is subject
    to change.

    I have successfully used this in my analyzer integration tests to get
    timing information about which source files get slowed down by the
    analyzer.  I've validated the generated .sarif files against the SARIF
    schema.

    gcc/ChangeLog:
            PR analyzer/109361
            * diagnostic-client-data-hooks.h (class sarif_object): New forward
            decl.
            (diagnostic_client_data_hooks::add_sarif_invocation_properties):
            New vfunc.
            * diagnostic-format-sarif.cc: Include "diagnostic-format-sarif.h".
            (class sarif_invocation): Inherit from sarif_object rather than
            json::object.
            (class sarif_result): Likewise.
            (class sarif_ice_notification): Likewise.
            (sarif_object::get_or_create_properties): New.
            (sarif_invocation::prepare_to_flush): Add "context" param.  Use it
            to call the context's add_sarif_invocation_properties hook.
            (sarif_builder::flush_to_file): Pass m_context to
            sarif_invocation::prepare_to_flush.
            * diagnostic-format-sarif.h: New header.
            * doc/invoke.texi (Developer Options): Clarify that -ftime-report
            writes to stderr.  Document that if SARIF diagnostic output is
            requested then any timing information is written in JSON form as
            part of the SARIF output, rather than to stderr.
            * timevar.cc: Include "json.h".
            (timer::named_items::m_hash_map): Split out type into...
            (timer::named_items::hash_map_t): ...this new typedef.
            (timer::named_items::make_json): New function.
            (timevar_diff): New function.
            (make_json_for_timevar_time_def): New function.
            (timer::timevar_def::make_json): New function.
            (timer::make_json): New function.
            * timevar.h (class json::value): New forward decl.
            (timer::make_json): New decl.
            (timer::timevar_def::make_json): New decl.
            * tree-diagnostic-client-data-hooks.cc: Include
            "diagnostic-format-sarif.h" and "timevar.h".
            (compiler_data_hooks::add_sarif_invocation_properties): New vfunc
            implementation.

    gcc/testsuite/ChangeLog:
            PR analyzer/109361
            * c-c++-common/diagnostic-format-sarif-file-timevars-1.c: New test.
            * c-c++-common/diagnostic-format-sarif-file-timevars-2.c: New test.

    Signed-off-by: David Malcolm <dmalcolm@redhat.com>

[Bug analyzer/109361] RFE: SARIF output could contain timing/profile information

[dmalcolm at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=109361

David Malcolm <dmalcolm at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|ASSIGNED                    |RESOLVED
         Resolution|---                         |FIXED

--- Comment #6 from David Malcolm <dmalcolm at gcc dot gnu.org> ---
Implemented in trunk for gcc 14 by the above patch.