superslow `using` when active project is on high latency network #38813

jaakkor2 · 2020-12-10T08:14:19Z

julia> import Pkg; Pkg.activate(raw"\\my\share")
  Activating environment at `\\my\share\Project.toml`

julia> @time using CSV
171.318006 seconds (1.42 M allocations: 94.513 MiB, 0.02% gc time, 0.41% compilation time)

Ping time to the share server is about 195 ms. The slowness is not specific to CSV.jl.

With the default C:\Users\jaakkor2\.julia\environments\v1.6\Project.toml, using is reasonable

julia> @time using CSV
  1.096882 seconds (1.45 M allocations: 95.848 MiB, 2.26% gc time, 64.13% compilation time)

Contents of the \\my\share\Project.toml is only

[deps]
CSV = "336ed68f-0bac-5ca0-87d4-7b16caf5d00b"

Just reading the toml files is not dominating the time.

julia> @time read(raw"\\my\share\Project.toml",String)
  0.411608 seconds (17 allocations: 1.344 KiB)
julia> @time read(raw"\\my\share\Manifest.toml",String)
  0.385952 seconds (17 allocations: 4.078 KiB)

Version info, but same slowness occurs with Julia v1.5.3.

julia> versioninfo()
Julia Version 1.6.0-DEV.1675
Commit aa4f341294* (2020-12-06 18:56 UTC)
Platform Info:
  OS: Windows (x86_64-w64-mingw32)
  CPU: Intel(R) Core(TM) i7-8650U CPU @ 1.90GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-11.0.0 (ORCJIT, skylake)
Environment:
  JULIA_EDITOR = "C:\Program Files\Sublime Text 3\sublime_text.exe"
  JULIA_NUM_THREADS = 4

Next step is to have a look with https://docs.microsoft.com/en-us/sysinternals/downloads/procmon as was done in #36911.

The text was updated successfully, but these errors were encountered:

jaakkor2 · 2020-12-11T17:20:07Z

Output of https://docs.microsoft.com/en-us/sysinternals/downloads/procmon with entries that touch the remote share looks like this

3097×7 DataFrame
  Row │ Time of Day       Process Name  PID    Operation                           Path                                           Result           Detail
      │ String            String        Int64  String                              String?                                        String?          String?
──────┼───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
    1 │ 16:00:13.1574301  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
    2 │ 16:00:13.1590635  julia.exe     20256  QueryAllInformationFile             \\\\mymy\\share\\jaakkor2\\Project.toml        BUFFER OVERFLOW  CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A, AllocationSize: 56, EndOfFile: 52, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x76800000000266e, EaSize: 0, Access: None 0x0, Position: 0, Mode: , AlignmentRequirement: Byte
    3 │ 16:00:13.1591195  julia.exe     20256  QueryInformationVolume              \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          VolumeCreationTime: 2019-03-15 13:41:07, VolumeSerialNumber: EA5C-6F18, SupportsObjects: True, VolumeLabel:
    4 │ 16:00:13.1981231  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
    5 │ 16:00:13.1981571  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
    6 │ 16:00:13.2365098  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
    7 │ 16:00:13.2375741  julia.exe     20256  QueryAllInformationFile             \\\\mymy\\share\\jaakkor2\\Project.toml        BUFFER OVERFLOW  CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A, AllocationSize: 56, EndOfFile: 52, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x76800000000266e, EaSize: 0, Access: None 0x0, Position: 0, Mode: , AlignmentRequirement: Byte
    8 │ 16:00:13.2376185  julia.exe     20256  QueryInformationVolume              \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          VolumeCreationTime: 2019-03-15 13:41:07, VolumeSerialNumber: EA5C-6F18, SupportsObjects: True, VolumeLabel:
    9 │ 16:00:13.2376647  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
   10 │ 16:00:13.2376945  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
   11 │ 16:00:13.2915097  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
   12 │ 16:00:13.2928081  julia.exe     20256  QueryBasicInformationFile           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A
   13 │ 16:00:13.2928547  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
   14 │ 16:00:13.2928897  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
   15 │ 16:00:13.3211346  julia.exe     20256  CreateFile                          \\\\mymy\\share\\                              SUCCESS          Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
   16 │ 16:00:13.3625721  julia.exe     20256  QueryDirectory                      \\\\mymy\\share\\jaakkor2                      SUCCESS          Filter: jaakkor2, 1: jaakkor2, FileInformationClass: FileBothDirectoryInformation
   17 │ 16:00:13.3626671  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\                              SUCCESS          missing
   18 │ 16:00:13.3627071  julia.exe     20256  CloseFile                           \\\\mymy\\share\\                              SUCCESS          missing
   19 │ 16:00:13.4101208  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
   20 │ 16:00:13.4114182  julia.exe     20256  QueryAllInformationFile             \\\\mymy\\share\\jaakkor2\\Project.toml        BUFFER OVERFLOW  CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A, AllocationSize: 56, EndOfFile: 52, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x76800000000266e, EaSize: 0, Access: None 0x0, Position: 0, Mode: , AlignmentRequirement: Byte
   21 │ 16:00:13.4114701  julia.exe     20256  QueryInformationVolume              \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          VolumeCreationTime: 2019-03-15 13:41:07, VolumeSerialNumber: EA5C-6F18, SupportsObjects: True, VolumeLabel:
   22 │ 16:00:13.4115228  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
   23 │ 16:00:13.4115580  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
   24 │ 16:00:13.4387128  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
   25 │ 16:00:13.4396385  julia.exe     20256  QueryAllInformationFile             \\\\mymy\\share\\jaakkor2\\Project.toml        BUFFER OVERFLOW  CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A, AllocationSize: 56, EndOfFile: 52, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x76800000000266e, EaSize: 0, Access: None 0x0, Position: 0, Mode: , AlignmentRequirement: Byte
   26 │ 16:00:13.4396816  julia.exe     20256  QueryInformationVolume              \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          VolumeCreationTime: 2019-03-15 13:41:07, VolumeSerialNumber: EA5C-6F18, SupportsObjects: True, VolumeLabel:
   27 │ 16:00:13.4397182  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
   28 │ 16:00:13.4397390  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
   29 │ 16:00:13.4984649  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
   30 │ 16:00:13.5001458  julia.exe     20256  QueryBasicInformationFile           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A
   31 │ 16:00:13.5001993  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
   32 │ 16:00:13.5002334  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
   33 │ 16:00:13.5265075  julia.exe     20256  CreateFile                          \\\\mymy\\share\\                              SUCCESS          Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
   34 │ 16:00:13.5269195  julia.exe     20256  QueryDirectory                      \\\\mymy\\share\\jaakkor2                      SUCCESS          Filter: jaakkor2, 1: jaakkor2, FileInformationClass: FileBothDirectoryInformation
   35 │ 16:00:13.5269851  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\                              SUCCESS          missing
   36 │ 16:00:13.5270131  julia.exe     20256  CloseFile                           \\\\mymy\\share\\                              SUCCESS          missing
   37 │ 16:00:13.5555493  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
   38 │ 16:00:13.5564915  julia.exe     20256  QueryAllInformationFile             \\\\mymy\\share\\jaakkor2\\Project.toml        BUFFER OVERFLOW  CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A, AllocationSize: 56, EndOfFile: 52, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x76800000000266e, EaSize: 0, Access: None 0x0, Position: 0, Mode: , AlignmentRequirement: Byte
  ⋮   │        ⋮               ⋮          ⋮                    ⋮                                         ⋮                               ⋮                                                                                                                                                                                               ⋮
 3060 │ 16:00:40.9841666  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: N, ShareMode: None, AllocationSize: n/a, OpenResult: Opened
 3061 │ 16:00:40.9855887  julia.exe     20256  QueryNameInformationFile            \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Name: \\mymy\\share\\jaakkor2\\Project.toml
 3062 │ 16:00:40.9856759  julia.exe     20256  QueryNameInformationFile            \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Name: \\mymy\\share\\jaakkor2\\Project.toml
 3063 │ 16:00:40.9857297  julia.exe     20256  QueryNormalizedNameInformationFile  \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
 3064 │ 16:00:41.0049512  julia.exe     20256  QueryNameInformationFile            \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Name: \\mymy\\share\\jaakkor2\\Project.toml
 3065 │ 16:00:41.0050946  julia.exe     20256  QueryNameInformationFile            \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Name: \\mymy\\share\\jaakkor2\\Project.toml
 3066 │ 16:00:41.0051559  julia.exe     20256  QueryNormalizedNameInformationFile  \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
 3067 │ 16:00:41.0288278  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
 3068 │ 16:00:41.0288667  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
 3069 │ 16:00:41.0705086  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
 3070 │ 16:00:41.0729019  julia.exe     20256  QueryAllInformationFile             \\\\mymy\\share\\jaakkor2\\Project.toml        BUFFER OVERFLOW  CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A, AllocationSize: 56, EndOfFile: 52, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x76800000000266e, EaSize: 0, Access: None 0x0, Position: 0, Mode: , AlignmentRequirement: Byte
 3071 │ 16:00:41.0729511  julia.exe     20256  QueryInformationVolume              \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          VolumeCreationTime: 2019-03-15 13:41:07, VolumeSerialNumber: EA5C-6F18, SupportsObjects: True, VolumeLabel:
 3072 │ 16:00:41.0730007  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
 3073 │ 16:00:41.0730306  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
 3074 │ 16:00:41.1044164  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
 3075 │ 16:00:41.1061252  julia.exe     20256  QueryAllInformationFile             \\\\mymy\\share\\jaakkor2\\Project.toml        BUFFER OVERFLOW  CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A, AllocationSize: 56, EndOfFile: 52, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x76800000000266e, EaSize: 0, Access: None 0x0, Position: 0, Mode: , AlignmentRequirement: Byte
 3076 │ 16:00:41.1061754  julia.exe     20256  QueryInformationVolume              \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          VolumeCreationTime: 2019-03-15 13:41:07, VolumeSerialNumber: EA5C-6F18, SupportsObjects: True, VolumeLabel:
 3077 │ 16:00:41.1062258  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
 3078 │ 16:00:41.1062559  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Project.toml        SUCCESS          missing
 3079 │ 16:00:41.1340650  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\JuliaManifest.toml  NAME NOT FOUND   Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
 3080 │ 16:00:41.1654097  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
 3081 │ 16:00:41.1664097  julia.exe     20256  QueryAllInformationFile             \\\\mymy\\share\\jaakkor2\\Manifest.toml       BUFFER OVERFLOW  CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A, AllocationSize: 4,096, EndOfFile: 2,604, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1a00000000caab, EaSize: 0, Access: None 0x0, Position: 0, Mode: , AlignmentRequirement: Byte
 3082 │ 16:00:41.1664472  julia.exe     20256  QueryInformationVolume              \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          VolumeCreationTime: 2019-03-15 13:41:07, VolumeSerialNumber: EA5C-6F18, SupportsObjects: True, VolumeLabel:
 3083 │ 16:00:41.1664955  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          missing
 3084 │ 16:00:41.1665391  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          missing
 3085 │ 16:00:41.2177996  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
 3086 │ 16:00:41.2188079  julia.exe     20256  QueryBasicInformationFile           \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A
 3087 │ 16:00:41.2188371  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          missing
 3088 │ 16:00:41.2188493  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          missing
 3089 │ 16:00:41.2440073  julia.exe     20256  CreateFile                          \\\\mymy\\share\\                              SUCCESS          Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
 3090 │ 16:00:41.2445644  julia.exe     20256  QueryDirectory                      \\\\mymy\\share\\jaakkor2                      SUCCESS          Filter: jaakkor2, 1: jaakkor2, FileInformationClass: FileBothDirectoryInformation
 3091 │ 16:00:41.2446385  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\                              SUCCESS          missing
 3092 │ 16:00:41.2446670  julia.exe     20256  CloseFile                           \\\\mymy\\share\\                              SUCCESS          missing
 3093 │ 16:00:41.2729385  julia.exe     20256  CreateFile                          \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
 3094 │ 16:00:41.2741127  julia.exe     20256  QueryAllInformationFile             \\\\mymy\\share\\jaakkor2\\Manifest.toml       BUFFER OVERFLOW  CreationTime: 2020-12-11 15:59:12, LastAccessTime: 2020-12-11 15:59:30, LastWriteTime: 2020-12-11 15:59:30, ChangeTime: 2020-12-11 15:59:30, FileAttributes: A, AllocationSize: 4,096, EndOfFile: 2,604, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1a00000000caab, EaSize: 0, Access: None 0x0, Position: 0, Mode: , AlignmentRequirement: Byte
 3095 │ 16:00:41.2741497  julia.exe     20256  QueryInformationVolume              \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          VolumeCreationTime: 2019-03-15 13:41:07, VolumeSerialNumber: EA5C-6F18, SupportsObjects: True, VolumeLabel:
 3096 │ 16:00:41.2741992  julia.exe     20256  QueryRemoteProtocolInformation      \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          missing
 3097 │ 16:00:41.2742279  julia.exe     20256  CloseFile                           \\\\mymy\\share\\jaakkor2\\Manifest.toml       SUCCESS          missing
                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 3021 rows omitted

Using a snippet

using CSV, DataFrames
a = CSV.read("Logfile.csv", DataFrame)
#filter!(:Operation => ≠("Process Profiling"), a)
filter!(:Path => !ismissing, a)
filter!(:Path => x -> !contains(x, "CSC"), a) # Windows offline caches in C:\Windows\CSC ?
filter!(:Path => x -> contains(x, "mymy"), a) # files on the share
show(a, truncate = 500)
filter!(:Operation => ==("CreateFile"), a) # The CreateFile function can create a new file or open an existing file. https://docs.microsoft.com/en-us/windows/win32/fileio/opening-a-file-for-reading-or-writing
for fn in unique(a.Path)
	a1 = filter(:Path => x -> contains(x, fn), a)
	println(fn, " ", nrow(a1))
end

outputs for the number of CreateFile operations

\\mymy\share\jaakkor2\Project.toml 396
\\mymy\share\ 671
\\mymy\share\jaakkor2\JuliaManifest.toml 36
\\mymy\share\jaakkor2\Manifest.toml 109
\\mymy\share\jaakkor2\JuliaLocalPreferences.toml 1
\\mymy\share\jaakkor2\LocalPreferences.toml 1

To summarize, when calling using , the environment toml files are opened and closed tens or even hundreds of times. If those files are on a high latency remote share, using is really slow.

oscardssmith · 2020-12-11T17:24:41Z

How big are the tomls? could we just read them all into memmory once and keep them until using is done?

jaakkor2 · 2020-12-11T17:36:15Z

In this demo case, Project.toml is two lines, Manifest.toml is 98 lines. Just what ones gets from starting a new project and ]add CSV.

KristofferC · 2020-12-11T18:48:54Z

Try with nightly, it should be improved there (the result get cached).

jaakkor2 · 2020-12-11T19:26:45Z

Problems with nightly #38838

jaakkor2 · 2020-12-15T08:02:11Z

Same behavior with latest nightly Version 1.7.0-DEV.77 (2020-12-15) Commit 80ace52b03 (0 days old master) I get

julia> @time using CSV
150.220530 seconds (592.84 k allocations: 45.539 MiB, 0.01% gc time, 0.07% compilation time)

Simple file read read(raw"\\mymy\share\jaakkor2\Project.toml", String) results in events

 Row │ Time of Day       Process Name  PID    Operation                       Path                                                                                Result          Detail
     │ String            String        Int64  String                          String?                                                                             String          String?
─────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
  57 │ 08:31:17.3691158  julia.exe     18300  CreateFile                      C:\\Windows\\CSC\\v2.0.6\\namespace\\mymy                                  NAME NOT FOUND  Desired Access: Read EA, Write EA, Read Attributes, Write Attributes, Delete, Read Control, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
  58 │ 08:31:17.3951269  julia.exe     18300  CreateFile                      \\\\mymy\\share\\jaakkor2\\Project.toml                                    SUCCESS         Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened
  59 │ 08:31:17.3953834  julia.exe     18300  CreateFile                      C:\\Windows\\CSC\\v2.0.6\\namespace\\mymy                                  NAME NOT FOUND  Desired Access: Read EA, Write EA, Read Attributes, Write Attributes, Delete, Read Control, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
  60 │ 08:31:17.4515818  julia.exe     18300  CreateFile                      C:\\Windows\\CSC\\v2.0.6\\namespace\\mymy                                  NAME NOT FOUND  Desired Access: Read EA, Write EA, Read Attributes, Write Attributes, Delete, Read Control, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
  61 │ 08:31:17.4517340  julia.exe     18300  CreateFile                      C:\\Windows\\CSC\\v2.0.6\\namespace\\mymy                                  NAME NOT FOUND  Desired Access: Read EA, Write EA, Read Attributes, Write Attributes, Delete, Read Control, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
  62 │ 08:31:17.4518266  julia.exe     18300  QueryDeviceInformationVolume    \\\\mymy\\share\\jaakkor2\\Project.toml                                    SUCCESS         DeviceType: Disk, Characteristics: Remote
  63 │ 08:31:17.4518527  julia.exe     18300  ReadFile                        \\\\mymy\\share\\jaakkor2\\Project.toml                                    SUCCESS         Offset: 0, Length: 52, Priority: Normal
  64 │ 08:31:17.4518877  julia.exe     18300  ReadFile                        \\\\mymy\\share\\jaakkor2\\Project.toml                                    SUCCESS         Offset: 0, Length: 52, I/O Flags: Non-cached, Paging I/O, Priority: Normal
  65 │ 08:31:17.4638683  julia.exe     18300  QueryRemoteProtocolInformation  \\\\mymy\\share\\jaakkor2\\Project.toml                                    SUCCESS         missing
  66 │ 08:31:17.4638878  julia.exe     18300  CloseFile                       \\\\mymy\\share\\jaakkor2\\Project.toml                                    SUCCESS         missing

If I filter the procmon logfile from using CSV for ReadFile operations, I get

\\mymy\share\jaakkor2\Project.toml 2
\\mymy\share\jaakkor2\Manifest.toml 2

i.e., environment files are only read once (or twice). But filtering for QueryAllInformationFile shows that access details are queried many times

\\mymy\share\jaakkor2\Project.toml 266
\\mymy\share\jaakkor2\Manifest.toml 72

As a bonus, I think this is a competitive entry to the TTFP contest 😀 with Version 1.7.0-DEV.77 (2020-12-15) Commit 80ace52b03 (0 days old master)

julia> @time using Plots
1339.681111 seconds (5.93 M allocations: 439.276 MiB, 0.01% gc time, 0.05% compilation time)

When the activated environment is on the local disk, using is reasonable

julia> @time using Plots
  6.309642 seconds (5.92 M allocations: 438.328 MiB, 1.81% gc time, 14.76% compilation time)

KristofferC · 2020-12-15T08:34:39Z

Can you try with this branch: https://github.com/JuliaLang/julia/tree/kc/assume_unchanged_loading

jaakkor2 · 2020-12-15T09:30:45Z

No practical improvement

julia> @time using CSV
assume_unchanged = false
assume_unchanged = true
assume_unchanged = true
...
assume_unchanged = true
assume_unchanged = true
110.671670 seconds (604.55 k allocations: 45.223 MiB, 0.05% gc time, 0.15% compilation time)

Julia Version 1.7.0-DEV.78
Commit d9749f45f3 (2020-12-15 08:33 UTC)

KristofferC · 2020-12-15T12:27:19Z

Hm, I thought that would remove the stat calls. Is the procmon log the same?

jaakkor2 · 2020-12-15T13:19:14Z

Procmon log says that

Project.toml and Manifest.toml are read only once with operation ReadFile.
Project.toml is accessed 165 times with operation QueryAllInformationFile

[This is in a different machine than above, but numbers are of the same order.]

mgkuhn added domain:packages Package management and loading system:windows Affects only Windows labels Dec 10, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

superslow `using` when active project is on high latency network #38813

superslow `using` when active project is on high latency network #38813

jaakkor2 commented Dec 10, 2020

jaakkor2 commented Dec 11, 2020

oscardssmith commented Dec 11, 2020

jaakkor2 commented Dec 11, 2020

KristofferC commented Dec 11, 2020 •

edited

jaakkor2 commented Dec 11, 2020

jaakkor2 commented Dec 15, 2020

KristofferC commented Dec 15, 2020

jaakkor2 commented Dec 15, 2020

KristofferC commented Dec 15, 2020

jaakkor2 commented Dec 15, 2020

superslow using when active project is on high latency network #38813

superslow using when active project is on high latency network #38813

Comments

jaakkor2 commented Dec 10, 2020

jaakkor2 commented Dec 11, 2020

oscardssmith commented Dec 11, 2020

jaakkor2 commented Dec 11, 2020

KristofferC commented Dec 11, 2020 • edited

jaakkor2 commented Dec 11, 2020

jaakkor2 commented Dec 15, 2020

KristofferC commented Dec 15, 2020

jaakkor2 commented Dec 15, 2020

KristofferC commented Dec 15, 2020

jaakkor2 commented Dec 15, 2020

superslow `using` when active project is on high latency network #38813

superslow `using` when active project is on high latency network #38813

KristofferC commented Dec 11, 2020 •

edited