Inconsistent Runtime of XLA Compiled Model Inference
@benson-guo, I was able to replicate the issue in Ubuntu 20.04 using tensorflow 2.11.  Kindly check the output below
@tilakrayal, please look at this issue. Thank you!
```
Iteration 0 time: 2445.906400680542
Iteration 1 time: 1.2180805206298828
Iteration 2 time: 0.8792877197265625
Iteration 3 time: 0.7956027984619141
Iteration 4 time: 0.8134841918945312
Iteration 5 time: 0.8347034454345703
Iteration 6 time: 0.7798671722412109
Iteration 7 time: 0.7691383361816406
Iteration 8 time: 0.79345703125
Iteration 9 time: 0.8080005645751953
Iteration 10 time: 0.8664131164550781
Iteration 11 time: 0.8289813995361328
Iteration 12 time: 0.8101463317871094
Iteration 13 time: 0.78582763671875
Iteration 14 time: 0.7910728454589844
Iteration 15 time: 0.8423328399658203
Iteration 16 time: 0.8206367492675781
Iteration 17 time: 0.8051395416259766
Iteration 18 time: 0.7901191711425781
Iteration 19 time: 0.8213520050048828
Iteration 20 time: 0.8761882781982422
Iteration 21 time: 0.8149147033691406
Iteration 22 time: 0.858306884765625
Iteration 23 time: 0.7889270782470703
Iteration 24 time: 0.8196830749511719
Iteration 25 time: 0.7832050323486328
Iteration 26 time: 0.8084774017333984
Iteration 27 time: 0.8132457733154297
Iteration 28 time: 0.8044242858886719
Iteration 29 time: 0.8461475372314453
Iteration 30 time: 0.7991790771484375
Iteration 31 time: 0.8070468902587891
Iteration 32 time: 0.8008480072021484
Iteration 33 time: 0.7684230804443359
Iteration 34 time: 0.8289813995361328
Iteration 35 time: 0.7951259613037109
Iteration 36 time: 0.8077621459960938
Iteration 37 time: 0.8130073547363281
Iteration 38 time: 2.5610923767089844
Iteration 39 time: 6.946086883544922
Iteration 40 time: 6.997823715209961
Iteration 41 time: 6.977558135986328
Iteration 42 time: 6.984710693359375
Iteration 43 time: 6.985187530517578
Iteration 44 time: 6.985664367675781
Iteration 45 time: 6.982564926147461
Iteration 46 time: 6.853818893432617
Iteration 47 time: 6.2713623046875
Iteration 48 time: 6.274938583374023
Iteration 49 time: 6.271839141845703
(tf) ynandi@sindhu-ubuntu-20-04:~$ 
 @synandi @tilakrayal 

Thanks for a having a look. For reference, I had also posted this in the TF forums: https://discuss.tensorflow.org/t/inconsistent-runtime-of-compiled-model-inference/14895. 

Someone had suggested it could be due to thermal throttling, but I was not able to notice a drop in core clock speed. This issue has been automatically marked as stale because it has no recent activity. It will be closed if no further activity occurs. Thank you.
 @benson-guo,
I tried to execute the code with **iterations=50 and iterations=100** and observed that the runtime was increased at different points in both cases. It might be due to the computations happening in the middle of the code and also it depends on the GPU where we were trying to execute the code.

**Iterations:100**

2023-03-01 09:13:19.755700: I tensorflow/compiler/jit/xla_compilation_cache.cc:477] Compiled cluster using XLA!  This line is logged at most once for the lifetime of the process.
Iteration 0 time: 2830.5792808532715
Iteration 1 time: 1.2085437774658203
Iteration 2 time: 0.9257793426513672
Iteration 3 time: 0.8394718170166016
Iteration 4 time: 0.8671283721923828
Iteration 5 time: 0.804901123046875
Iteration 6 time: 0.8020401000976562
Iteration 7 time: 0.8029937744140625
Iteration 8 time: 0.7991790771484375
Iteration 9 time: 0.8249282836914062
Iteration 10 time: 0.8022785186767578
Iteration 11 time: 0.7832050323486328
Iteration 12 time: 0.8487701416015625
Iteration 13 time: 0.8215904235839844
Iteration 14 time: 0.7920265197753906
Iteration 15 time: 0.8149147033691406
Iteration 16 time: 0.7905960083007812
Iteration 17 time: 0.7901191711425781
Iteration 18 time: 0.8051395416259766
Iteration 19 time: 0.7903575897216797
Iteration 20 time: 0.8058547973632812
Iteration 21 time: 0.7767677307128906
Iteration 22 time: 0.8132457733154297
Iteration 23 time: 0.7922649383544922
Iteration 24 time: 0.7941722869873047
Iteration 25 time: 0.7932186126708984
Iteration 26 time: 0.7929801940917969
Iteration 27 time: 0.8213520050048828
Iteration 28 time: 0.7803440093994141
Iteration 29 time: 0.7965564727783203
Iteration 30 time: 0.7948875427246094
Iteration 31 time: 0.8120536804199219
Iteration 32 time: 0.8111000061035156
Iteration 33 time: 0.7951259613037109
Iteration 34 time: 0.7946491241455078
Iteration 35 time: 0.7963180541992188
Iteration 36 time: 0.8103847503662109
Iteration 37 time: 0.7822513580322266
**Iteration 38 time: 0.7915496826171875
Iteration 39 time: 4.862785339355469
Iteration 40 time: 6.767034530639648**
Iteration 41 time: 6.778955459594727
Iteration 42 time: 6.768226623535156
Iteration 43 time: 6.769895553588867
Iteration 44 time: 6.781578063964844
Iteration 45 time: 6.75511360168457
Iteration 46 time: 6.757020950317383
Iteration 47 time: 6.769657135009766
Iteration 48 time: 6.767749786376953
Iteration 49 time: 6.76274299621582
Iteration 50 time: 6.770610809326172
Iteration 51 time: 6.770133972167969
Iteration 52 time: 6.761789321899414
Iteration 53 time: 6.768226623535156
Iteration 54 time: 6.76727294921875
Iteration 55 time: 6.767988204956055
Iteration 56 time: 6.771087646484375
Iteration 57 time: 6.768465042114258
Iteration 58 time: 6.776332855224609
Iteration 59 time: 6.762504577636719
Iteration 60 time: 6.757020950317383
Iteration 61 time: 6.764411926269531
Iteration 62 time: 6.769895553588867
Iteration 63 time: 6.777286529541016
Iteration 64 time: 6.75654411315918
Iteration 65 time: 6.771326065063477
Iteration 66 time: 6.752252578735352
Iteration 67 time: 6.765127182006836
Iteration 68 time: 6.781578063964844
Iteration 69 time: 6.740093231201172
Iteration 70 time: 6.770610809326172
Iteration 71 time: 6.651401519775391
Iteration 72 time: 6.081104278564453
Iteration 73 time: 6.009101867675781
Iteration 74 time: 5.947589874267578
Iteration 75 time: 5.949735641479492
Iteration 76 time: 5.953550338745117
Iteration 77 time: 5.947351455688477
Iteration 78 time: 5.955934524536133
Iteration 79 time: 5.97071647644043
Iteration 80 time: 6.098508834838867
Iteration 81 time: 6.084680557250977
Iteration 82 time: 6.083011627197266
Iteration 83 time: 6.061077117919922
Iteration 84 time: 6.080389022827148
Iteration 85 time: 6.068229675292969
Iteration 86 time: 6.074428558349609
Iteration 87 time: 6.0787200927734375
Iteration 88 time: 6.091594696044922
Iteration 89 time: 6.074190139770508
Iteration 90 time: 6.08372688293457
Iteration 91 time: 6.079673767089844
Iteration 92 time: 6.080865859985352
Iteration 93 time: 6.078004837036133
Iteration 94 time: 6.106138229370117
Iteration 95 time: 6.051301956176758
Iteration 96 time: 5.996227264404297
Iteration 97 time: 5.947113037109375
Iteration 98 time: 5.954742431640625
Iteration 99 time: 6.06536865234375
Iteration 100 time: 6.131410598754883

`Iterations:100`

2023-03-01 09:08:55.643995: I tensorflow/compiler/jit/xla_compilation_cache.cc:477] Compiled cluster using XLA!  This line is logged at most once for the lifetime of the process.
Iteration 0 time: 3033.7562561035156
Iteration 1 time: 2.8045177459716797
Iteration 2 time: 0.9644031524658203
Iteration 3 time: 0.8635520935058594
Iteration 4 time: 0.8149147033691406
Iteration 5 time: 0.8897781372070312
Iteration 6 time: 0.8149147033691406
Iteration 7 time: 0.8230209350585938
Iteration 8 time: 0.8220672607421875
Iteration 9 time: 0.7984638214111328
Iteration 10 time: 0.8337497711181641
Iteration 11 time: 0.7987022399902344
Iteration 12 time: 0.7767677307128906
Iteration 13 time: 0.8323192596435547
Iteration 14 time: 0.7944107055664062
Iteration 15 time: 0.7920265197753906
Iteration 16 time: 0.7965564727783203
Iteration 17 time: 0.7848739624023438
Iteration 18 time: 0.8008480072021484
Iteration 19 time: 0.8194446563720703
Iteration 20 time: 0.79345703125
Iteration 21 time: 0.7944107055664062
Iteration 22 time: 0.7903575897216797
Iteration 23 time: 0.8323192596435547
Iteration 24 time: 0.7834434509277344
Iteration 25 time: 0.7383823394775391
Iteration 26 time: 0.7770061492919922
Iteration 27 time: 0.7696151733398438
Iteration 28 time: 0.8041858673095703
Iteration 29 time: 0.7872581481933594
Iteration 30 time: 0.8168220520019531
Iteration 31 time: 0.7634162902832031
Iteration 32 time: 0.8182525634765625
Iteration 33 time: 0.7886886596679688
Iteration 34 time: 0.8273124694824219
Iteration 35 time: 0.7882118225097656
**Iteration 36 time: 0.8006095886230469
Iteration 37 time: 7.169246673583984
Iteration 38 time: 11.08241081237793**
Iteration 39 time: 11.090517044067383
Iteration 40 time: 11.073827743530273
Iteration 41 time: 11.065483093261719
Iteration 42 time: 11.078357696533203
Iteration 43 time: 9.224891662597656
Iteration 44 time: 9.146690368652344
Iteration 45 time: 9.139060974121094
Iteration 46 time: 9.15384292602539
Iteration 47 time: 9.148120880126953
Iteration 48 time: 9.152650833129883
Iteration 49 time: 9.154081344604492
Iteration 50 time: 9.14454460144043

Also we observed that the change in the runtime was not at the same interval point for every execution. Thank you! Hi @tilakrayal 

So I was reading from this paper (https://hal-lirmm.ccsd.cnrs.fr/lirmm-03775613/document) that in eager async mode, tensorflow operations can return handles that have not been computed yet. To see if that's the case for the compiled function, I tried to force the computation to synchronously execute before the end of the timing block by adding a conditional branch dependent on the result of the inference.

```
import tensorflow as tf
import time

model = tf.keras.Sequential()
layers = 15
for _ in range(layers):
    model.add(tf.keras.layers.Conv2D(3, 3, data_format="channels_first"))
model_input = tf.random.uniform(shape=(12, 3, 256, 256))
xla_fn = tf.function(model, jit_compile=True)
iterations = 100
for i in range(iterations):
    start_time = time.time()
    model_out = xla_fn(model_input)
    # if statement conditional on model output
    if tf.reshape(model_out, -1)[0] == 0:
        print("")
    end_time = time.time()
    print(f"Iteration {i} time: {1000 * (end_time - start_time)}")
```

The resulting profiled runtimes seems consistent now after a few iterations.
Iteration 0 time: 5936.74898147583
Iteration 1 time: 22.758007049560547
Iteration 2 time: 22.4761962890625
Iteration 3 time: 22.189855575561523
Iteration 4 time: 22.08256721496582
Iteration 5 time: 22.035837173461914
Iteration 6 time: 22.022485733032227
Iteration 7 time: 22.035837173461914
Iteration 8 time: 22.036075592041016
Iteration 9 time: 22.014141082763672
Iteration 10 time: 22.00603485107422
Iteration 11 time: 20.064592361450195
Iteration 12 time: 20.070552825927734
Iteration 13 time: 20.066499710083008
Iteration 14 time: 20.09725570678711
Iteration 15 time: 20.081281661987305
Iteration 16 time: 19.88387107849121
Iteration 17 time: 19.904375076293945
Iteration 18 time: 19.907712936401367
Iteration 19 time: 19.498825073242188
Iteration 20 time: 18.95761489868164
Iteration 21 time: 18.933773040771484
Iteration 22 time: 18.957853317260742
Iteration 23 time: 18.938302993774414
Iteration 24 time: 18.92995834350586
Iteration 25 time: 18.850088119506836
Iteration 26 time: 18.827438354492188
Iteration 27 time: 18.799543380737305
Iteration 28 time: 18.813371658325195
Iteration 29 time: 18.778562545776367
Iteration 30 time: 18.76211166381836
Iteration 31 time: 18.78190040588379
Iteration 32 time: 18.78833770751953
Iteration 33 time: 18.79286766052246
Iteration 34 time: 18.782615661621094
Iteration 35 time: 18.767595291137695
Iteration 36 time: 18.773317337036133
Iteration 37 time: 18.77903938293457
Iteration 38 time: 18.7833309173584
Iteration 39 time: 18.78976821899414
Iteration 40 time: 18.793344497680664
Iteration 41 time: 18.777132034301758
Iteration 42 time: 18.792390823364258
Iteration 43 time: 18.752336502075195
Iteration 44 time: 18.66936683654785
Iteration 45 time: 18.666505813598633
Iteration 46 time: 18.671274185180664
Iteration 47 time: 18.65530014038086
Iteration 48 time: 18.67055892944336
Iteration 49 time: 18.663644790649414
Iteration 50 time: 18.662452697753906
Iteration 51 time: 18.65530014038086
Iteration 52 time: 18.648862838745117
Iteration 53 time: 18.680095672607422
Iteration 54 time: 18.678665161132812
Iteration 55 time: 18.626928329467773
Iteration 56 time: 18.750905990600586
Iteration 57 time: 19.0277099609375
Iteration 58 time: 18.60952377319336
Iteration 59 time: 18.702030181884766
Iteration 60 time: 18.656492233276367
Iteration 61 time: 18.646717071533203
Iteration 62 time: 18.682479858398438
Iteration 63 time: 18.665552139282227
Iteration 64 time: 18.663644790649414
Iteration 65 time: 18.66936683654785
Iteration 66 time: 18.670082092285156
Iteration 67 time: 18.667221069335938
Iteration 68 time: 18.694162368774414
Iteration 69 time: 18.665313720703125
Iteration 70 time: 18.650054931640625
Iteration 71 time: 18.680095672607422
Iteration 72 time: 18.672943115234375
Iteration 73 time: 18.646717071533203
Iteration 74 time: 18.663406372070312
Iteration 75 time: 18.650531768798828
Iteration 76 time: 18.599510192871094
Iteration 77 time: 18.951892852783203
Iteration 78 time: 18.95451545715332
Iteration 79 time: 18.649816513061523
Iteration 80 time: 18.6614990234375
Iteration 81 time: 18.665313720703125
Iteration 82 time: 18.66745948791504
Iteration 83 time: 18.651247024536133
Iteration 84 time: 18.673419952392578
Iteration 85 time: 18.68128776550293
Iteration 86 time: 18.65100860595703
Iteration 87 time: 18.670082092285156
Iteration 88 time: 18.661975860595703
Iteration 89 time: 18.643856048583984
Iteration 90 time: 18.65553855895996
Iteration 91 time: 18.65553855895996
Iteration 92 time: 18.65363121032715
Iteration 93 time: 18.638134002685547
Iteration 94 time: 18.673419952392578
Iteration 95 time: 18.662452697753906
Iteration 96 time: 18.665313720703125
Iteration 97 time: 18.625259399414062
Iteration 98 time: 18.651723861694336
Iteration 99 time: 18.649816513061523

So am I right to conclude that the issue is caused by asynchronous execution? And if so, is there a low overhead method of forcing the execution to synchronize for timing purpopses?

I had also tried
`tf.config.experimental.set_synchronous_execution(enable=False)`
But that still leads to weird timing.
 Hi, @benson-guo 

Apologize for the delayed response and I was able to replicate the same issue with our latest `TF2.12` and `tf-nightly` with `Tesla T4 GPU `allocated by Google Colab and for your reference I have added [gist-file](https://colab.research.google.com/gist/gaikwadrahul8/d171c331bc4e8745574577e4d1565291/-59719.ipynb) and at the moment I'm not sure what is root cause for this inconsistent runtime of XLA compiled model inference so we'll have to dig more into this issue and we'll update soon. Thank you! Ok, thanks for looking into this! @benson-guo I just noticed your issue. And actually you understood alone your problem. Let me completely answer it for you :)

Tensorflow is eager first. When you return from an execution you get "sort of an eager pointer" to the result that is not yet populated.

One way to force trigger the resync `result = model(data).numpy()`. Unfortunately this triggers a memcpyDtoH which not only introduces a lot of overhead if the output tensor is large but also a lot of jitter.

`tf.config.experimental.set_synchronous_execution(enable=False)` this API does not work on GPU ;)

Though, you're in luck :D and the solution is easy. After some long discussion with @reedwm we published this RFC: https://github.com/tensorflow/community/pull/434 which led to this commit: https://github.com/tensorflow/tensorflow/commit/267c63aa0938682ca7b1990dcf09f041495db1fa

Now allow me to quickly rewrite your code:

```python
import tensorflow as tf
import time

model = tf.keras.Sequential()
layers = 15
for _ in range(layers):
    model.add(tf.keras.layers.Conv2D(3, 3, data_format="channels_first"))
    
model_input = tf.random.uniform(shape=(12, 3, 256, 256))
xla_fn = tf.function(model, jit_compile=True)

iterations = 100

for i in range(iterations):
    start_time = time.perf_counter()  # time.time() is not suitable for benchmarking
    model_out = xla_fn(model_input)
    tf.test.experimental.sync_devices()  # Force GPU resync point - Sync about it as "waiting for the pipeline of async ops to clear out"
    end_time = time.perf_counter()
    print(f"Iteration {i} time: {1000 * (end_time - start_time)}")
```

Please close the issue if this address all your concerns ;)  @DEKHTIARJonathan Thanks, this is exactly what I was looking for! I guess I couldn't find it because it was added so recently :)

I saw some TF documentation where they time functions without this synchronization, which would not be accurate on the GPU at least (e.g. https://www.tensorflow.org/guide/function#usage). Do you think the documentation should be updated to add this experimental synchronization or have a disclaimer about this issue?) I already mentioned the issue to @reedwm and @yarri-oss . Yes the documentation should be updated accross the board to include `tf.test.experimental.sync_devices()`

CC: @nluehr @pjannaty > I already mentioned the issue to @reedwm and @yarri-oss . Yes the documentation should be updated accross the board to include `tf.test.experimental.sync_devices()`
> 
> CC: @nluehr @pjannaty

Yeah in https://www.tensorflow.org/guide/function#usage, the time printed in the `timeit` part of the tutorial is unreasonably short because a GPU is used and `sync_devices` wasn't called.

Adding a call to `sync_devices` would make the example very verbose, as it forces the lambdas to be made into top-level functions. Maybe the `numpy` method should be used instead of `sync_devices` for conciseness, e.g. by replacing the third-to-last line in the `timeit` code block with

```
print("Eager conv:", timeit.timeit(lambda: conv_layer(image).numpy(), number=10))
```

CC @MarkDaoust  @reedwm I disagree. We implemented `tf.test.experimental.sync_devices()` precisely for this usecase. Let's not introduce poor/bad practices in the official documentation.

`.numpy()` is NOT a good idea to measure / assess performance. Hence we had to come up with `sync_devices()` `numpy` also measures the device transfer time, which sometimes you want, but you're right this example does not want to measure this, since it's just comparing the performance of `tf.function`.

Perhaps the example with `timeit` should be removed. I don't think the example adds much value since it doesn't show `tf.function` being faster, even if `sync_devices` is added.


<details><summary>Click to expand!</summary> 
 
 ### Issue Type

Performance

### Have you reproduced the bug with TF nightly?

No

### Source

binary

### Tensorflow Version

2.11

### Custom Code

Yes

### OS Platform and Distribution

Ubuntu 20.04

### Mobile device

_No response_

### Python version

3.8.13

### Bazel version

_No response_

### GCC/Compiler version

_No response_

### CUDA/cuDNN version

11.6

### GPU model and memory

_No response_

### Current Behaviour?

```shell
Hi, I am trying to measure the runtime of a jit compiled model inference using time.time(). Code and output is provided below.

From my understanding, I would expect the first iteration to take longer since the function needs to be traced and compiled. However, I’m confused why the runtime from iteration 36 and onwards increases significantly. Is there an issue with the way I am measuring the runtime? If not, what would explain the increase in runtime?

I am running this on a P40 GPU by the way on tf 2.11. I had tried to run the same code on the nightly version but got the error "*** TypeError: expected bytes, tensorflow.python.client._pywrap_tf_session.StringBuffer found" when calling the compiled function. Thanks in advance.
```


### Standalone code to reproduce the issue

```shell
import tensorflow as tf
import time

model = tf.keras.Sequential()
layers = 15
for _ in range(layers):
    model.add(tf.keras.layers.Conv2D(3, 3, data_format="channels_first"))
model_input = tf.random.uniform(shape=(12, 3, 256, 256))
xla_fn = tf.function(model, jit_compile=True)
iterations = 50
for i in range(iterations):
    start_time = time.time()
    xla_fn(model_input)
    end_time = time.time()
    print(f"Iteration {i} time: {1000 * (end_time - start_time)}")
```


### Relevant log output

```shell
Iteration 0 time: 6884.105682373047
Iteration 1 time: 1.5869140625
Iteration 2 time: 1.2054443359375
Iteration 3 time: 1.1410713195800781
Iteration 4 time: 1.1148452758789062
Iteration 5 time: 1.1096000671386719
Iteration 6 time: 1.1081695556640625
Iteration 7 time: 1.1057853698730469
Iteration 8 time: 1.1026859283447266
Iteration 9 time: 1.0957717895507812
Iteration 10 time: 1.115560531616211
Iteration 11 time: 1.100301742553711
Iteration 12 time: 1.1072158813476562
Iteration 13 time: 1.0993480682373047
Iteration 14 time: 1.102447509765625
Iteration 15 time: 1.100778579711914
Iteration 16 time: 1.0983943939208984
Iteration 17 time: 1.111745834350586
Iteration 18 time: 1.0929107666015625
Iteration 19 time: 1.0929107666015625
Iteration 20 time: 1.10626220703125
Iteration 21 time: 1.1260509490966797
Iteration 22 time: 1.1012554168701172
Iteration 23 time: 1.0957717895507812
Iteration 24 time: 1.1103153228759766
Iteration 25 time: 1.0924339294433594
Iteration 26 time: 1.0981559753417969
Iteration 27 time: 1.0950565338134766
Iteration 28 time: 1.1153221130371094
Iteration 29 time: 1.0952949523925781
Iteration 30 time: 1.100301742553711
Iteration 31 time: 1.1081695556640625
Iteration 32 time: 1.0983943939208984
Iteration 33 time: 1.0955333709716797
Iteration 34 time: 1.0974407196044922
Iteration 35 time: 1.1048316955566406
Iteration 36 time: 13.811588287353516
Iteration 37 time: 18.66292953491211
Iteration 38 time: 18.66936683654785
Iteration 39 time: 18.68462562561035
Iteration 40 time: 18.68152618408203
Iteration 41 time: 19.069910049438477
Iteration 42 time: 17.874717712402344
Iteration 43 time: 18.11075210571289
Iteration 44 time: 18.109560012817383
Iteration 45 time: 18.10741424560547
Iteration 46 time: 18.124818801879883
Iteration 47 time: 18.130064010620117
Iteration 48 time: 17.90904998779297
Iteration 49 time: 17.884492874145508
```
</details>