Skip to content

== [[StatsReportListener]] StatsReportListener -- Logging Summary Statistics

org.apache.spark.scheduler.StatsReportListener (see https://spark.apache.org/docs/latest/api/scala/index.html#org.apache.spark.scheduler.StatsReportListener[the listener's scaladoc]) is a ROOT:SparkListener.md[] that logs summary statistics when each stage completes.

StatsReportListener listens to ROOT:SparkListener.md#SparkListenerTaskEnd[SparkListenerTaskEnd] and ROOT:SparkListener.md#SparkListenerStageCompleted[SparkListenerStageCompleted] events and prints them out at INFO logging level.

[TIP]

Enable INFO logging level for org.apache.spark.scheduler.StatsReportListener logger to see Spark events.

Add the following line to conf/log4j.properties:

log4j.logger.org.apache.spark.scheduler.StatsReportListener=INFO

Refer to spark-logging.md[Logging].

=== [[onStageCompleted]] Intercepting Stage Completed Events -- onStageCompleted Callback

CAUTION: FIXME

=== [[example]] Example

$ ./bin/spark-shell -c spark.extraListeners=org.apache.spark.scheduler.StatsReportListener
...
INFO SparkContext: Registered listener org.apache.spark.scheduler.StatsReportListener
...

scala> spark.read.text("README.md").count
...
INFO StatsReportListener: Finished stage: Stage(0, 0); Name: 'count at <console>:24'; Status: succeeded; numTasks: 1; Took: 212 msec
INFO StatsReportListener: task runtime:(count: 1, mean: 198.000000, stdev: 0.000000, max: 198.000000, min: 198.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   198.0 ms    198.0 ms    198.0 ms    198.0 ms    198.0 ms    198.0 ms    198.0 ms    198.0 ms    198.0 ms
INFO StatsReportListener: shuffle bytes written:(count: 1, mean: 59.000000, stdev: 0.000000, max: 59.000000, min: 59.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   59.0 B  59.0 B  59.0 B  59.0 B  59.0 B  59.0 B  59.0 B  59.0 B  59.0 B
INFO StatsReportListener: fetch wait time:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms
INFO StatsReportListener: remote bytes read:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
INFO StatsReportListener: task result size:(count: 1, mean: 1885.000000, stdev: 0.000000, max: 1885.000000, min: 1885.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   1885.0 B    1885.0 B    1885.0 B    1885.0 B    1885.0 B    1885.0 B    1885.0 B    1885.0 B    1885.0 B
INFO StatsReportListener: executor (non-fetch) time pct: (count: 1, mean: 73.737374, stdev: 0.000000, max: 73.737374, min: 73.737374)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   74 %    74 %    74 %    74 %    74 %    74 %    74 %    74 %    74 %
INFO StatsReportListener: fetch wait time pct: (count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:    0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %
INFO StatsReportListener: other time pct: (count: 1, mean: 26.262626, stdev: 0.000000, max: 26.262626, min: 26.262626)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   26 %    26 %    26 %    26 %    26 %    26 %    26 %    26 %    26 %
INFO StatsReportListener: Finished stage: Stage(1, 0); Name: 'count at <console>:24'; Status: succeeded; numTasks: 1; Took: 34 msec
INFO StatsReportListener: task runtime:(count: 1, mean: 33.000000, stdev: 0.000000, max: 33.000000, min: 33.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   33.0 ms 33.0 ms 33.0 ms 33.0 ms 33.0 ms 33.0 ms 33.0 ms 33.0 ms 33.0 ms
INFO StatsReportListener: shuffle bytes written:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
INFO StatsReportListener: fetch wait time:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms
INFO StatsReportListener: remote bytes read:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
INFO StatsReportListener: task result size:(count: 1, mean: 1960.000000, stdev: 0.000000, max: 1960.000000, min: 1960.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   1960.0 B    1960.0 B    1960.0 B    1960.0 B    1960.0 B    1960.0 B    1960.0 B    1960.0 B    1960.0 B
INFO StatsReportListener: executor (non-fetch) time pct: (count: 1, mean: 75.757576, stdev: 0.000000, max: 75.757576, min: 75.757576)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   76 %    76 %    76 %    76 %    76 %    76 %    76 %    76 %    76 %
INFO StatsReportListener: fetch wait time pct: (count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:    0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %
INFO StatsReportListener: other time pct: (count: 1, mean: 24.242424, stdev: 0.000000, max: 24.242424, min: 24.242424)
INFO StatsReportListener:   0%  5%  10% 25% 50% 75% 90% 95% 100%
INFO StatsReportListener:   24 %    24 %    24 %    24 %    24 %    24 %    24 %    24 %    24 %
res0: Long = 99

Last update: 2020-10-06