board_ms365() tests are really slow

[hadley]

They're taking > 80s for me. @hongooi73 did anything change lately? I don't remember them being this slow when I last worked on pins.

[hongooi73]

I haven't changed anything, but Microsoft365R isn't that optimised. The server could also just be slow right now.

Does profiling show any obvious bottlenecks?

[lemuelemos]

i'm having the same problem. When a try to pin some large DT i'm having the error:

"Error in curl::curl_fetch_memory(url, handle = handle) : OpenSSL SSL_read: SSL_ERROR_SYSCALL, errno 104"

I can't pin large datasets.

[hadley]

@lemuelemos that's not the same problem. Please create a reprex and file a new issue.

[hongooi73]

I ran a profile on test-board_ms365.R, and it took ~5 minutes to run the MS365 check. It looks like 90% of the time is spent waiting for the server:

r$> summaryRprof("~/misc/pins_profile.out")
$by.self
                          self.time self.pct total.time total.pct
"curl::curl_fetch_memory"       298    90.85        298     90.85
"curl::curl_fetch_disk"          27     8.23         27      8.23
"cat"                             1     0.30          1      0.30
"sub"                             1     0.30          1      0.30
"validate"                        1     0.30          1      0.30

I can have a look at whether there are any API calls that can be stripped out.

I also found a bug in board_ms365_test_driveitem which I'll make a PR for.

[hongooi73]

The detailed profile output. Nothing really stands out....

``` $by.total total.time total.pct self.time self.pct "test" 328 100.00 0 0.00 "testthat::test_local" 328 100.00 0 0.00 "FUN" 327 99.70 0 0.00 "lapply" 327 99.70 0 0.00 "test_dir" 327 99.70 0 0.00 "test_files" 327 99.70 0 0.00 "with_reporter" 327 99.70 0 0.00 "doTryCatch" 326 99.39 0 0.00 "doWithOneRestart" 326 99.39 0 0.00 "eval" 326 99.39 0 0.00 "force" 326 99.39 0 0.00 "source_file" 326 99.39 0 0.00 "test_code" 326 99.39 0 0.00 "tryCatch" 326 99.39 0 0.00 "tryCatchList" 326 99.39 0 0.00 "tryCatchOne" 326 99.39 0 0.00 "withCallingHandlers" 326 99.39 0 0.00 "withOneRestart" 326 99.39 0 0.00 "withRestarts" 326 99.39 0 0.00 "request_fetch" 325 99.09 0 0.00 "request_perform" 325 99.09 0 0.00 "" 316 96.34 0 0.00 "testthat::test_that" 314 95.73 0 0.00 "curl::curl_fetch_memory" 298 90.85 298 90.85 "request_fetch.write_memory" 298 90.85 0 0.00 "call_graph_endpoint" 278 84.76 0 0.00 "call_graph_url" 278 84.76 0 0.00 "httr::VERB" 277 84.45 0 0.00 "test_api_versioning" 151 46.04 0 0.00 "pin_store" 125 38.11 0 0.00 "pin_store.pins_board_ms365" 125 38.11 0 0.00 "test_api_basic" 125 38.11 0 0.00 "pin_write" 119 36.28 0 0.00 "pin_delete" 118 35.98 0 0.00 "pin_delete.pins_board_ms365" 118 35.98 0 0.00 "ms365_delete_dir" 103 31.40 0 0.00 "child$delete" 93 28.35 0 0.00 "ms365_list_dirs" 86 26.22 0 0.00 "%in%" 77 23.48 0 0.00 "pin_exists" 77 23.48 0 0.00 "pin_exists.pins_board_ms365" 77 23.48 0 0.00 "self$do_operation" 64 19.51 0 0.00 "local_pin" 60 18.29 0 0.00 "pin_meta" 50 15.24 0 0.00 "pin_meta.pins_board_ms365" 50 15.24 0 0.00 "pin_fetch" 49 14.94 0 0.00 "pin_fetch.pins_board_ms365" 49 14.94 0 0.00 "httr::PUT" 48 14.63 0 0.00 "initialize" 48 14.63 0 0.00 "test_api_meta" 48 14.63 0 0.00 "file.path" 47 14.33 0 0.00 "ms_drive_item$new" 47 14.33 0 0.00 "check_pin_exists" 46 14.02 0 0.00 "ms365_download" 39 11.89 0 0.00 "super$delete" 35 10.67 0 0.00 "version_setup" 35 10.67 0 0.00 ".External2" 34 10.37 0 0.00 "eval_bare" 34 10.37 0 0.00 "quasi_label" 31 9.45 0 0.00 "testthat::expect_equal" 29 8.84 0 0.00 "pin_read" 28 8.54 0 0.00 "pin_versions" 28 8.54 0 0.00 "pin_versions.pins_board_ms365" 28 8.54 0 0.00 "pin_versions_modern" 28 8.54 0 0.00 "curl::curl_fetch_disk" 27 8.23 27 8.23 "request_fetch.write_disk" 27 8.23 0 0.00 "pin_download" 21 6.40 0 0.00 "self$list_items" 21 6.40 0 0.00 "call_batch_endpoint" 20 6.10 0 0.00 "self$get_item" 19 5.79 0 0.00 "%||%" 13 3.96 0 0.00 "check_pin_version" 13 3.96 0 0.00 "last" 13 3.96 0 0.00 "version_from_path" 9 2.74 0 0.00 "versions_template" 9 2.74 0 0.00 "try" 8 2.44 0 0.00 "ms365_file_exists" 6 1.83 0 0.00 "pin_upload" 6 1.83 0 0.00 ".capture" 3 0.91 0 0.00 "expect_condition_matching" 3 0.91 0 0.00 "pin_version_delete" 3 0.91 0 0.00 "pin_version_delete.pins_board_ms365" 3 0.91 0 0.00 "quasi_capture" 3 0.91 0 0.00 "testthat::expect_error" 3 0.91 0 0.00 "nrow" 2 0.61 0 0.00 "private$get_root" 2 0.61 0 0.00 "cat" 1 0.30 1 0.30 "sub" 1 0.30 1 0.30 "validate" 1 0.30 1 0.30 "board_ms365" 1 0.30 0 0.00 "board_ms365_test_charpath" 1 0.30 0 0.00 "board_ms365_test_driveitem" 1 0.30 0 0.00 "cat_line" 1 0.30 0 0.00 "cli::cat_rule" 1 0.30 0 0.00 "desc_desc_get" 1 0.30 0 0.00 "description$new" 1 0.30 0 0.00 "drive$create_folder" 1 0.30 0 0.00 "drv$create_folder" 1 0.30 0 0.00 "httr::content" 1 0.30 0 0.00 "idesc_create" 1 0.30 0 0.00 "idesc_create_file" 1 0.30 0 0.00 "idesc_create_text" 1 0.30 0 0.00 "is.factor" 1 0.30 0 0.00 "jsonlite::fromJSON" 1 0.30 0 0.00 "mysub" 1 0.30 0 0.00 "o_apply" 1 0.30 0 0.00 "parse_auto" 1 0.30 0 0.00 "parser" 1 0.30 0 0.00 "pkgload::pkg_name" 1 0.30 0 0.00 "process_response" 1 0.30 0 0.00 "read.dcf" 1 0.30 0 0.00 "read_dcf" 1 0.30 0 0.00 "reporter$end_reporter" 1 0.30 0 0.00 "self$rule" 1 0.30 0 0.00 "testthat::expect_false" 1 0.30 0 0.00 "testthat::expect_true" 1 0.30 0 0.00 "trimws" 1 0.30 0 0.00 ```

[hadley]

Hmmm, maybe we should switch to smaller data files? I'm going to be working on pins again this week, so I'll hopefully have refamiliarised myself with what's going on shortly.

[hadley]

Looks like there's nothing obvious we can do to improve performance so I'm going to close this. If I get too annoyed by how long it takes these tests to run, I might add some skip functionality based on an env var.

[github-actions[bot]]

This issue has been automatically locked. If you believe you have found a related problem, please file a new issue (with a reprex: https://reprex.tidyverse.org) and link to this issue.