rstudio / shinyloadtest

Tools for load testing Shiny applications
https://rstudio.github.io/shinyloadtest/
110 stars 22 forks source link

[Bug] Date in report doesn't match the recording time. #130

Open ColinFay opened 4 years ago

ColinFay commented 4 years ago

When I record a session with shinycannon, the date in the JSON column doesn't match the time of the recording.

> library(purrr)
> Sys.time()
[1] "2020-04-10 14:10:11 CEST"
> system("shinycannon shinylogs/recording.log http://localhost:2811 --workers 2 --output-dir shinylogs/runreprex")
2020-04-10 14:10:12.875 INFO [progress] - Running: 0, Failed: 0, Done: 0
2020-04-10 14:10:12.875 INFO [thread00] - Waiting for warmup to complete
2020-04-10 14:10:12.875 INFO [thread01] - Warming up
2020-04-10 14:10:17.882 INFO [progress] - Running: 1, Failed: 0, Done: 0
2020-04-10 14:10:22.883 INFO [progress] - Running: 1, Failed: 0, Done: 0
2020-04-10 14:10:27.888 INFO [progress] - Running: 1, Failed: 0, Done: 0
2020-04-10 14:10:32.890 INFO [progress] - Running: 1, Failed: 0, Done: 0
2020-04-10 14:10:36.851 INFO [thread02] - Warming up
2020-04-10 14:10:36.852 INFO [thread00] - Maintaining for 0 minutes (0 ms)
2020-04-10 14:10:36.852 INFO [thread00] - Stopped maintaining, waiting for workers to stop
2020-04-10 14:10:37.894 INFO [progress] - Running: 2, Failed: 0, Done: 0
2020-04-10 14:10:42.896 INFO [progress] - Running: 2, Failed: 0, Done: 0
2020-04-10 14:10:47.900 INFO [progress] - Running: 2, Failed: 0, Done: 0
2020-04-10 14:10:52.904 INFO [progress] - Running: 2, Failed: 0, Done: 0
2020-04-10 14:10:57.904 INFO [progress] - Running: 2, Failed: 0, Done: 0
2020-04-10 14:11:01.763 INFO [thread01] - Stopped
2020-04-10 14:11:02.909 INFO [progress] - Running: 1, Failed: 0, Done: 1
2020-04-10 14:11:07.910 INFO [progress] - Running: 1, Failed: 0, Done: 1
2020-04-10 14:11:12.914 INFO [progress] - Running: 1, Failed: 0, Done: 1
2020-04-10 14:11:17.914 INFO [progress] - Running: 1, Failed: 0, Done: 1
2020-04-10 14:11:22.914 INFO [progress] - Running: 1, Failed: 0, Done: 1
2020-04-10 14:11:27.461 INFO [thread02] - Stopped
2020-04-10 14:11:27.461 INFO [thread00] - Complete. Failed: 0, Done: 2
> Sys.time()
[1] "2020-04-10 14:11:27 CEST"
> shinyload_runs <- shinyloadtest::load_runs("2 workers" = "shinylogs/runreprex")
1 workers [============================================================================================] 4/4 eta: 0s
> 
> Sys.time()
[1] "2020-04-10 14:11:29 CEST"
> map(shinyload_runs$json, "begin") %>%
+   map(lubridate::ymd_hms) %>%
+   map(lubridate::with_tz, tzone = "Europe/Paris") %>%
+   head()
[[1]]
[1] "2020-04-10 08:54:55 CEST"

[[2]]
[1] "2020-04-10 08:54:55 CEST"

[[3]]
[1] "2020-04-10 08:54:55 CEST"

[[4]]
[1] "2020-04-10 08:54:55 CEST"

[[5]]
[1] "2020-04-10 08:54:55 CEST"

[[6]]
[1] "2020-04-10 08:54:55 CEST"

As you can see, it's not even a timezone issue, the events are recorded as beginning at minute xx:55, while the test have been run at xx:10.