Skip to content

POC Json Progress Logger / Streamer - #1018

Merged
dantleech merged 1 commit into
masterfrom
json
Mar 7, 2026
Merged

dantleech merged 1 commit into
masterfrom
json

Conversation

@dantleech

Copy link
Copy Markdown
Member

This PR adds support for streaming results via. a JSON progress logger:

./bin/phpbench run --progress=json  | jq

@dantleech
dantleech force-pushed the json branch 3 times, most recently from 0e75662 to 2a77b64 Compare March 7, 2026 11:32
@dantleech
dantleech merged commit 16ac6f2 into master Mar 7, 2026
14 checks passed
@dantleech
dantleech deleted the json branch March 7, 2026 11:34
@llaville

Copy link
Copy Markdown
Contributor

@dantleech I've just tested the PHAR distribution of version 1.6.0 and got error with yq tool.

/shared/backups/phar/phpbench-1.6.phar run --progress=json --config=/shared/backups/github/phplint/phpbench.json tests/Benchmark/ | yq -o json
{
  "benchmark": "LintCommandBench",
  "subject": "benchDefaultConfiguration",
  "variant": "",
  "iteration": 0,
  "time_net": 748317,
  "time_revs": 1,
  "time_avg": 748317,
  "mem_peak": 14434008,
  "mem_real": 16777216,
  "mem_final": 12465832
}
Error: bad file '-': yaml: line 1: did not find expected <document start>

Or with yq auto-detecting format

/shared/backups/phar/phpbench-1.6.phar run --progress=json --config=/shared/backups/github/phplint/phpbench.json tests/Benchmark/ | yq
{"benchmark": "LintCommandBench", "subject": "benchDefaultConfiguration", "variant": "", "iteration": 0, "time_net": 750203, "time_revs": 1, "time_avg": 750203, "mem_peak": 14426520, "mem_real": 16777216, "mem_final": 12465832}
Error: bad file '-': yaml: line 1: did not find expected <document start>

When I specify --verbose flag on yq command, I got this output

[DEBUG] 05:31:20 utils.go:269                      processStdInArgs          missing '-', adding it to the end
[DEBUG] 05:31:20 utils.go:235                      maybeFile                 checking '-' is a file
[DEBUG] 05:31:20 utils.go:240                      maybeFile                 error: stat -: no such file or directory
[DEBUG] 05:31:20 utils.go:244                      maybeFile                 result: false
[DEBUG] 05:31:20 utils.go:297                      processArgs               processed args: [-]
[DEBUG] 05:31:20 format.go:127                     FormatStringFromFilename  checking filename '-' for auto format detection
[DEBUG] 05:31:20 format.go:136                     FormatStringFromFilename  using default inputFormat 'yaml'
[DEBUG] 05:31:20 utils.go:107                      configureFormats          Using input format yaml
[DEBUG] 05:31:20 utils.go:108                      configureFormats          Using output format yaml
[DEBUG] 05:31:20 expression_parser.go:29           ParseExpression           Parsing expression: []
[DEBUG] 05:31:20 expression_postfix.go:47          ConvertToPostfix          postfix processing currentToken )
[DEBUG] 05:31:20 expression_postfix.go:127         ConvertToPostfix          opstackLen: 0
[DEBUG] 05:31:20 expression_postfix.go:138         ConvertToPostfix          PostFix Result:
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!map
[DEBUG] 05:31:23 candidate_node_yaml.go:119        UnmarshalYAML             UnmarshalYAML -  a mapping node
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:106        UnmarshalYAML             UnmarshalYAML !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:114        UnmarshalYAML             UnmarshalYAML -  a scalar
[DEBUG] 05:31:23 candidate_node_yaml.go:142        UnmarshalYAML             UnmarshalYAML -  finished mapping node
[DEBUG] 05:31:23 data_tree_navigator.go:54         GetMatchingNodes          getMatchingNodes - nothing to do
[DEBUG] 05:31:23 printer.go:73                     PrintResults              PrintResults for 1 matches
[DEBUG] 05:31:23 printer.go:100                    PrintResults              print sep logic: p.firstTimePrinting: false, previousDocIndex: 0
[DEBUG] 05:31:23 printer.go:101                    PrintResults              D0, P, MappingNode (!!map)::20 kids
[DEBUG] 05:31:23 encoder_yaml.go:32                Encode                    encoderYaml - going to print D0, P, MappingNode (!!map)::20 kids
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!map
[DEBUG] 05:31:23 candidate_node_yaml.go:198        MarshalYAML               original style: 32
[DEBUG] 05:31:23 candidate_node_yaml.go:199        MarshalYAML               original: D0, P, MappingNode (!!map)::20 kids, tag: !!map, style: 32, kind: false
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: benchmark
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: LintCommandBench
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: subject
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: benchDefaultConfiguration
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: variant
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar:
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: iteration
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: 0
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: time_net
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: 746508
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: time_revs
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: 1
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: time_avg
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: 746508
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: mem_peak
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: 14426872
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: mem_real
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: 16777216
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!str
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: mem_final
[DEBUG] 05:31:23 candidate_node_yaml.go:179        MarshalYAML               MarshalYAML to yaml: !!int
[DEBUG] 05:31:23 candidate_node_yaml.go:187        MarshalYAML               MarshalYAML - scalar: 12465832
{"benchmark": "LintCommandBench", "subject": "benchDefaultConfiguration", "variant": "", "iteration": 0, "time_net": 746508, "time_revs": 1, "time_avg": 746508, "mem_peak": 14426872, "mem_real": 16777216, "mem_final": 12465832}
[DEBUG] 05:31:23 printer.go:150                    PrintResults              done printing results
Error: bad file '-': yaml: line 1: did not find expected <document start>

Any idea about incompatibility ?

@dantleech

Copy link
Copy Markdown
Member Author

maybe try it with jq? I don't know why it's trying to interpret it as YAML

@dantleech

dantleech commented Mar 22, 2026 •

Copy link
Copy Markdown
Member Author

I get the same error with yq - I think it's expecting a full JSON document, but the progress logger is streaming individual json objects separted by new lines.

Using phpbench run --report=aggregate --output=json however provides a complete JSON doc:

./bin/phpbench run --report=aggregate --output=json --iterations=1 | yq

@llaville

Copy link
Copy Markdown
Contributor

I got very strange results/behavior on project https://github.com/overtrue/phplint where I am a contributor since a long time now !

Here is the full benchmark test suite running with only 1 iteration (as suggested in your previous comment)

phpbench-161-failed

And if I remove the benchJobs1000 test suite (see https://github.com/overtrue/phplint/blob/main/tests/Benchmark/Console/Command/LintCommandBench.php#L61-L64), I've got :

phpbench-161-passed

Is there something we could do to prevent such failure ?

@llaville

Copy link
Copy Markdown
Contributor

Related to #1136 (comment), I've try to apply it with :

My phpbench.json config file become (update not yet online)

{
  "report.generators": {
    "github-action-benchmark": {
      "cols": [
        "name",
        "unit",
        "value",
        "range",
        "extra"
      ],
      "expressions": {
        "name": "format('%s::%s%s', first(benchmark_name),first(subject_name),if(first(variant_name) != false, format(' (%s)', first(variant_name)), ''))",
        "unit": "coalesce(time_unit(first(subject_time_unit), true),'µs')",
        "value": "time_convert(mode(result_time_avg), 'us', time_unit(first(subject_time_unit)))",
        "range": "format('± %.2f%%', rstdev(result_time_avg))",
        "extra": "format('%d iterations, %d revs', first(variant_iterations), first(variant_revs))"
      },
      "aggregate": [
        "suite_tag",
        "benchmark_class",
        "subject_name",
        "variant_index"
      ],
      "generator": "expression"
    }
  },
  "runner.bootstrap": "autoload.php",
  "runner.php_disable_ini": true
}

But, if I run full benchmarks tests (including benchJobs100 I've no failure, but nothing is printed, if I specify --progress none flag. See following screenshots with 3 different attempts.

phpbench-161-progress-none

What was wrong in such condition ?

@dantleech

Copy link
Copy Markdown
Member Author

Is there something we could do to prevent such failure ?

this is a problem with phplint opening too many files - I don't think it's related to PHPBench. See https://stackoverflow.com/questions/14748499/fatal-error-too-many-open-files

@dantleech

dantleech commented Mar 23, 2026 •

Copy link
Copy Markdown
Member Author

What was wrong in such condition ?

Plase comment on the original PR or open an issue :) but you don't need to specify --progress=none (the progress is on the stderr stream, the JSON report is on stdout). I suspect you'll see the reason it failed if not silencing progress.

@llaville

llaville commented Mar 24, 2026 •

Copy link
Copy Markdown
Contributor

Thanks @dantleech : Changing the maximum number of open file descriptors with ulimit fixed the issue !

phpbench run --report=github-action-benchmark --progress=json --output json tests/Benchmark/ | yq -p json

Gave me : last chunk of progress json was displayed, and final report

phplint-98-sample

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants