I am trying to do a "naive measure time" (endTime - startTime) for some spark operations, to get an idea about different alternatives to do the same logic.
I am getting a decreasing processing time series from the loop. Why does it happen?
Let's say, for example, I am measuring the following simple operation:
def t1(): (Array[Row], Long) = measureElapsedTime {
val res = spark.read.json(nestedDF)
res.collect()
}
Measuring it the following way:
val n = 1000
def avg(f: () => (Array[Row], Long)) = 1.to(n).map(_ => f()._2).sum / n
println(avg(t1))
Would give me approximately 45 ms on average.
But, if I take a look at the head of the series, I see clearly a decrease in processing time. For example, the measured time in ms in order of execution, for the first executions:
707
157
144
119
153
108
99
105
121
107
132
89
96
100
83
93
87
94
73
Why does this pattern happen? Is this due to JVM warm-up time? Is this due to some spark optimization?
I don't think that the reason is JVM warm-up time because it doesn't happen for operations not reusing the "same" DF (and anyway, I added some other operations before the previous example to warm up the JVM). For example, the following gives virtually stable running time:
def t2(): (Array[Row], Long) = measureElapsedTime {
val res: Dataset[String] = nestedDF.map((str: String) => {
val json: Value = ujson.read(str)
ujson.write(json)
})
spark.read.json(res).collect()
}
Where running time series is:
44
141
93
92
79
78
79
84
76
80
78
77
71
71
70
71
103
74
69
72
Question background: I am measuring operations for a spark structured streaming app, so I am quite sure that for each micro-batch I would get the first measured value, since every micro-batch is a new DF. However I might be wrong, and this is the reason I am asking this question.
Thank you all.
Clarifications:
nestedDF in the examples above is a Dataset[String] with JSON string values.
+-----------------------------------------------------------------------------------------------+
|value |
+-----------------------------------------------------------------------------------------------+
|{"simple": "a", "nested": {"c1": "a"}} |
|{"simple": "a", "more-nested": {"c1": {"c11": {"c111": "a"}}}} |
|{"simple": "a", "nested-with-diff-types": {"array": ["a", "b"], "obj": {"c1": {"c11": "a"}}}}|
|{"simple": "a", "nested-with-array": {"c1": {"c11": ["a", "b", "c"]}}} |
|{"simple": "a", "nested-with-array-with-obj-elem": {"c1": {"c11": [{"a": "a"}, {"b": "b"}]}}}|
+-----------------------------------------------------------------------------------------------+