XLSX.writexlsx spends excessive time in gc on Windows

TimG · September 29, 2024, 10:08am

I need to create many Excel files in a batch. I use a common template and populate with different data and then write out the file to an IOBuffer() using XLSX.jl. This remains slower than I expected, even after this PR was merged.

When I try

xio = IOBuffer()
@time XLSX.writexlsx(xio, template)

inside a loop over all datasets, I get (for example)

...
  0.474708 seconds (6.47 k allocations: 1.295 MiB, 97.73% gc time)
  0.471064 seconds (6.45 k allocations: 1.269 MiB, 97.48% gc time)
  0.449121 seconds (6.45 k allocations: 1.269 MiB, 96.74% gc time)
  0.433755 seconds (6.45 k allocations: 1.269 MiB, 97.53% gc time)
  0.447344 seconds (6.46 k allocations: 1.295 MiB, 97.79% gc time)
  0.473887 seconds (6.46 k allocations: 1.270 MiB, 97.99% gc time)
  0.440383 seconds (6.47 k allocations: 1.270 MiB, 97.83% gc time)
...

I’ve had a go at basic profiling to try to see what is going on:

Profile - Click to expand


Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
   ╎279 @Base\client.jl:552; _start()
   ╎ 279 @Base\client.jl:318; exec_options(opts::Base.JLOptions)
   ╎  279 @Base\Base.jl:495; include(mod::Module, _path::String)
   ╎   279 @Base\loading.jl:2136; _include(mapexpr::Function, mod::Module, _path::String)
   ╎    279 @Base\loading.jl:2076; include_string(mapexpr::typeof(identity), mod::Module, code::String, filename::String)
   ╎     279 @Base\boot.jl:385; eval
   ╎    ╎ 279 @VSCodeDebugger\src\VSCodeDebugger.jl:45; startdebugger()
   ╎    ╎  279 @DebugAdapter\src\packagedef.jl:122; run(debug_session::VSCodeDebugger.DebugAdapter.DebugSession, error_handler::VSCodeDebugger.var"#3#4"{String})
   ╎    ╎   279 @Base\client.jl:489; include(fname::String)
   ╎    ╎    279 @Base\loading.jl:2136; _include(mapexpr::Function, mod::Module, _path::String)
   ╎    ╎     279 @Base\loading.jl:2076; include_string(mapexpr::typeof(identity), mod::Module, code::String, filename::String)
   ╎    ╎    ╎ 279 @Base\boot.jl:385; eval
   ╎    ╎    ╎  279 …ood Cause Summaries Team - General\Good Cause Summaries\Code\ChooseBatches.jl:47; chooseBatches()
   ╎    ╎    ╎   279 @Base\timing.jl:279; macro expansion
   ╎    ╎    ╎    279 … Team - General\Good Cause Summaries\Code\Template-jl-Library\lib-batches.jl:88; ProcessAllBatches(BatchFolders::DataFrame)
   ╎    ╎    ╎     279 … Team - General\Good Cause Summaries\Code\Template-jl-Library\lib-batches.jl:68; ProcessBatch(dir::String, dcms::DataFrame, remgrants::DataFrame)
   ╎    ╎    ╎    ╎ 279 @Base\timing.jl:279; macro expansion
   ╎    ╎    ╎    ╎  279 …s Team - General\Good Cause Summaries\Code\Template-jl-Library\lib-write.jl:144; writeTemplates(summaries::DataFrame, logIO::IOBuffer)
   ╎    ╎    ╎    ╎   279 @Profile\src\Profile.jl:44; macro expansion
   ╎    ╎    ╎    ╎    279 … Team - General\Good Cause Summaries\Code\Template-jl-Library\lib-write.jl:142; (::var"#x#67"{XLSX.XLSXFile})()
   ╎    ╎    ╎    ╎     279 @XLSX\src\write.jl:52; writexlsx(output_source::IOBuffer, xf::XLSX.XLSXFile)
   ╎    ╎    ╎    ╎    ╎ 2   @XLSX\src\write.jl:61; writexlsx(output_source::IOBuffer, xf::XLSX.XLSXFile; overwrite::Bool)
   ╎    ╎    ╎    ╎    ╎  1   @XLSX\src\write.jl:172; update_worksheets_xml!(xl::XLSX.XLSXFile)
   ╎    ╎    ╎    ╎    ╎   1   @EzXML\src\xpath.jl:79; findall(xpath::String, node::EzXML.Node, ns::Vector{Pair{String, String}})
   ╎    ╎    ╎    ╎    ╎    1   @EzXML\src\xpath.jl:136; new_xpath_context
  1╎    ╎    ╎    ╎    ╎  1   @XLSX\src\write.jl:233; update_worksheets_xml!(xl::XLSX.XLSXFile)
   ╎    ╎    ╎    ╎    ╎ 2   @XLSX\src\write.jl:63; writexlsx(output_source::IOBuffer, xf::XLSX.XLSXFile; overwrite::Bool)
   ╎    ╎    ╎    ╎    ╎  2   @ZipArchives\src\writer.jl:52; ZipWriter
   ╎    ╎    ╎    ╎    ╎   2   @ZipArchives\src\writer.jl:55; ZipWriter(f::XLSX.var"#44#45"{XLSX.XLSXFile}, io::IOBuffer; zip_kwargs::Base.Pairs{Symbol, Union{}, Tuple{}, @NamedTuple{}})
   ╎    ╎    ╎    ╎    ╎    1   @XLSX\src\write.jl:72; (::XLSX.var"#44#45"{XLSX.XLSXFile})(xlsx::ZipWriter{IOBuffer})
   ╎    ╎    ╎    ╎    ╎     1   @EzXML\src\document.jl:60; print
   ╎    ╎    ╎    ╎    ╎    ╎ 1   @EzXML\src\node.jl:310; print
   ╎    ╎    ╎    ╎    ╎    ╎  1   @EzXML\src\node.jl:340; dump_node(io::ZipWriter{IOBuffer}, node::EzXML.Node, format::Bool)
   ╎    ╎    ╎    ╎    ╎    ╎   1   @Base\strings\io.jl:250; print
   ╎    ╎    ╎    ╎    ╎    ╎    1   @Base\strings\io.jl:248; write
   ╎    ╎    ╎    ╎    ╎    ╎     1   @ZipArchives\src\writer.jl:307; unsafe_write(w::ZipWriter{IOBuffer}, p::Ptr{UInt8}, n::UInt64)
  1╎    ╎    ╎    ╎    ╎    ╎    ╎ 1   @ZipArchives\src\reader.jl:2; unsafe_crc32
   ╎    ╎    ╎    ╎    ╎    1   @XLSX\src\write.jl:77; (::XLSX.var"#44#45"{XLSX.XLSXFile})(xlsx::ZipWriter{IOBuffer})
   ╎    ╎    ╎    ╎    ╎     1   @ZipArchives\src\writer.jl:169; zip_newfile
   ╎    ╎    ╎    ╎    ╎    ╎ 1   @ZipArchives\src\writer.jl:178; zip_newfile(w::ZipWriter{IOBuffer}, name::String; comment::String, compress::Bool, compression_method::UInt16, compression_level::Int64, executable::Nothing, ext…
   ╎    ╎    ╎    ╎    ╎    ╎  1   @ZipArchives\src\writer.jl:334; zip_commitfile(w::ZipWriter{IOBuffer})
   ╎    ╎    ╎    ╎    ╎    ╎   1   @TranscodingStreams\src\stream.jl:524; write
   ╎    ╎    ╎    ╎    ╎    ╎    1   @TranscodingStreams\src\stream.jl:642; flush_buffer1(stream::TranscodingStreams.TranscodingStream{CodecZlib.DeflateCompressor, ZipArchives.WriteOffsetTracker{IOBuffer}})
   ╎    ╎    ╎    ╎    ╎    ╎     1   @TranscodingStreams\src\stream.jl:685; callprocess(stream::TranscodingStreams.TranscodingStream{CodecZlib.DeflateCompressor, ZipArchives.WriteOffsetTracker{IOBuffer}}, inbuf::TranscodingStr…
   ╎    ╎    ╎    ╎    ╎    ╎    ╎ 1   @CodecZlib\src\compression.jl:177; process(codec::CodecZlib.DeflateCompressor, input::TranscodingStreams.Memory, output::TranscodingStreams.Memory, error::TranscodingStreams.Error)
  1╎    ╎    ╎    ╎    ╎    ╎    ╎  1   @CodecZlib\src\libz.jl:77; deflate!
   ╎    ╎    ╎    ╎    ╎ 275 @XLSX\src\write.jl:87; writexlsx(output_source::IOBuffer, xf::XLSX.XLSXFile; overwrite::Bool)
   ╎    ╎    ╎    ╎    ╎  275 @Base\gcutils.jl:129; gc
275╎    ╎    ╎    ╎    ╎   275 @Base\gcutils.jl:129; gc
Total snapshots: 279. Utilization: 100% across all threads and tasks. Use the `groupby` kwarg to break down by thread and/or task.

Looking at line 87 in write.jl:

    # fix libuv issue on windows (#42)
    @static Sys.iswindows() ? GC.gc() : nothing

So I have several questions:

What is libuv and what is the libuv issue? How is the issue manifested in writexlsx.jl - in other words what might the consequences be if I deleted this line?
Are there plans to fix the libuv issue or is there a way to work around it? Has it perhaps already been fixed? (Issue #42 is closed)
Rejected PR #270 wanted to remove the related gc call from read.jl. Is it safe to do the same from write.jl?

Thanks for any help you can offer!

TimG · September 29, 2024, 11:40am

I have dev’d XLSX.jl and commented out line 87 from write.jl.

Now, when I try

@time XLSX.writexlsx(xio, template)

I get

...
  0.012716 seconds (6.45 k allocations: 1.294 MiB)
  0.011488 seconds (6.46 k allocations: 1.295 MiB)
  0.011399 seconds (6.44 k allocations: 1.269 MiB)
  0.011020 seconds (6.45 k allocations: 1.294 MiB)
  0.015902 seconds (6.46 k allocations: 1.295 MiB)
  0.013709 seconds (6.64 k allocations: 1.308 MiB)
  0.013524 seconds (6.45 k allocations: 1.269 MiB)
  0.014230 seconds (6.45 k allocations: 1.294 MiB)
...

This makes a huge difference, as you can see. I have not yet seen a downside, but I guess I’ll live in fear until I understand this better. In the mean time, it’s probably worth the risk…!?

Also, with this line deletion, XLSX.jl still passes all tests.

TimG · September 29, 2024, 12:01pm

Remove the gc call in write.jl by TimG1964 · Pull Request #271 · felipenoris/XLSX.jl (github.com)

I guess this will meet the same fate as PR #270, but it’s worth a go!

Palli · September 30, 2024, 6:36pm

Thanks for making the (now merged) PR removing the slow GC.gc() (for when writing).

I’m a bit concerned that it was (considered) needed for when reading, and it’s still slow, and that PR closed:

It’s considered (rightly?) needed because of a LibUV bug? And/or inappropriate implementation of XLSX for I/O? Should good programming not trigger that bug?

I think this has to do with finalizers, i.e. you want files closed, and the GC triggers it (but you (the package) could do it yourself?!). I’m very unclear why that would be needing when only reading files (and there it’s for all platforms, not just Windows).

If this is a workaround that works, and should be used, then I’m not at all sure that most users know of it, and maybe GC.gc() should document that it should be used for such? Or that it’s a bad workaround? Where is the best workaround, where should it be documented?

FYI: GC.gc() is used by Julia itself (in recent version, at least since 10 months ago), and that function seems to be called for you when you exit Julia:

github.com

JuliaLang/julia/blob/2a2878c143b87e5184565c895d090aab6e9017e9/base/file.jl#L658-L672


      
          function temp_cleanup_purge_all()
              may_need_gc = false
              @lock TEMP_CLEANUP_LOCK filter!(TEMP_CLEANUP) do (path, asap)
                  try
                      ispath(path) || return false
                      may_need_gc = true
                      return true
                  catch ex
                      ex isa InterruptException && rethrow()
                      return true
                  end
              end
              if may_need_gc
                  # this is only usually required on Sys.iswindows(), but may as well do it everywhere
                  GC.gc(true)

github.com

JuliaLang/julia/blob/2a2878c143b87e5184565c895d090aab6e9017e9/base/file.jl#L678-L682


      
          # deprecated internal function used by some packages
          temp_cleanup_purge(; force=false) = force ? temp_cleanup_purge_all() : @lock TEMP_CLEANUP_LOCK temp_cleanup_purge_prelocked(false)
          
          function __postinit__()
              Base.atexit(temp_cleanup_purge_all)

This PR is about a different (or same?) LibUV bug:

TimG · September 30, 2024, 8:44pm

I’m afraid I can’t answer your questions - you’ve made many connections I wasn’t aware of and which are well beyond me. You will have seen in the OP that I really don’t understand what the libUV “bug” is and was just speculatively trying to remove the source of slowness in my use case. That it worked was just good luck rather than any actual skill or judgement on my part.

Issue #252 points out that the GC.gc “fix” is used in openxlsx too, but only when using the do syntax. So, for reading, too, you can avoid the slowdown by closing the file explicitly. Why is the fix only needed for the do syntax when reading? I have absolutely no idea. I presume that simply deleting the GC call (as I did for writing) causes an issue, and this is why PR 270 failed, but I have no idea why this would be so.

nhz2 · September 30, 2024, 10:56pm

It is important to close files when reading files on Windows because, unlike Unix, on Windows files that are open for reading sometimes cannot be deleted or renamed. Calling GC.gc may be closing some files that were accidentally left open and are no longer referenced by the program.

There is also a fishy use of a finalizer at XLSX.jl/src/types.jl at 214fa73972c198bb39c562a4ec2d8b5002cfe73d · felipenoris/XLSX.jl · GitHub. This should probably be removed and replaced with finalizers in EzXML.jl and CodecZlib.jl where memory is allocated by C libraries.

TimG · October 3, 2024, 10:32am

My skill level can be described as rudimentary at best. Never the less, I’ve spent some time going through the XLSX.jl code for reading to look for opened files that remain un-closed. I can’t understand the code very well, but I cannot find any unclosed file. I’m also unsure why the finalizer @nhz2 mentions is fishy (not saying it isn’t fishy, just that I don’t understand why).

It seems that it is the readtable function that gives rise to the problem found by the tests. As far as I can tell, EzXML.jl only accesses IOBuffers created by ZipArchives.jl, so shouldn’t be able to lock the file to prevent its removal (is that true?). Only ZipArchives.jl actually accesses the file on disk, and I can’t find any open files that remains unclosed. I’ve obviously missed something, but I’ve no idea what.

I think it’ll take someone with more knowledge/skill than me to track this down.

TimG · October 3, 2024, 10:49pm

Well, I lost heart too soon!

Remove GC.gc call from read.jl by TimG1964 · Pull Request #272 · felipenoris/XLSX.jl (github.com)

Don’t know why it works, but it does!

Palli · October 3, 2024, 11:44pm

All files can be (opened and) closed explicitly in Julia (though usually not done that way), as in C, but usually you just open files, and close implicitly as there with:

github.com

felipenoris/XLSX.jl/blob/214fa73972c198bb39c562a4ec2d8b5002cfe73d/src/read.jl#L52-L57


      
          This function should be used with `do` syntax, like in:
          
          ```julia
          XLSX.openxlsx("myfile.xlsx") do xf
              # read data from `xf`
          end

When you hit the end there Julia would close the file implicitly, at least ideally, by calling the defined finalizer, that has that job (to close files or “destruct”, that word is a misnomer when referring to files, it applies to “destructing” the file handle which means closing), because of the do.

Although the do block syntax does have certain similarities to Python’s with statement, there is no exact equivalent. This is discussed in further detail in the GitHub issue “with for deterministic destruction”. The issue concludes that this structure should be added to Julia, although no syntax or plan for such is established.

This is one of Julia’s oldest open issue, from 2014 (commented on up to 2023):

github.com/JuliaLang/julia

`with` for deterministic destruction

opened 01:24AM - 25 Jul 14 UTC

klaufir

speculative design

**Deterministic destruction** Deterministic destruction is a guarantee that some… specified resources will be released when exiting from the enclosing block even if we exit from the block by the means of exceptions. **Example** In python deterministic destruction is done using the `with` statement. ``` python with open("myfile","w") as f: f.write("Hello") ``` Considering the code above we don't have to worry about closing a file explicitly. After the `with` block, the file will be closed. Even when something throws an exception inside the `with` block, the resources handled by the `with` statement will be released (in this case closed). **Other languages** - C++ always had guaranteed destructor calls at scope exit for stack objects - even in the face of exceptions (see [RAII](http://en.wikipedia.org/wiki/Resource_Acquisition_Is_Initialization)). - In C# there is the [`using` statement](http://msdn.microsoft.com/en-us/library/yh598w02.aspx) for this same purpose. - Java has [try-with-resources](http://docs.oracle.com/javase/tutorial/essential/exceptions/tryResourceClose.html) since Java7. **Julia?** It is my firm belief that Julia also needs to have a feature supporting deterministic destruction. We have countless cases when a resource needs to be closed at soon as possible: serial ports, database connections, some external api handles, files, etc. In cases like these deterministic destruction would mean cleaner code, no explicit `close()` / `release()` calls and no sandwiching the code in `try` .. `catch` .. `finally` blocks.

I think, but I’m not sure, that in Python with is guaranteed to close, so might it then be better to use PythonCall for some I/O libaries…? (and if so because Python uses reference counting, not tracing GC only like Julia, at least in default [C]Python, seemingly might not apply in e.g. Jython or PyPy):

[Note, __del__ methods are Python’s finalizers.]

https://doc.pypy.org/en/latest/cpython_differences.html

Here are some more technical details. This issue affects the precise time at which del methods are called, which is not reliable or timely in PyPy (nor Jython nor IronPython). It also means that weak references may stay alive for a bit longer than expected.

That argument applies to writing files equally (and even more). On non-Windows, you’re saying it’s not important ever to close files that you only read (any exceptions to that? when accessing Samba? you might not know which files in your file-system are on such an external mount point).

When you’re writing you must of course flush your data to the file, or it could get lost. The package will be responsible for that, and only in the end when you close the file will it be flushed again if needed (but I think that’s not an issue here). When Julia closes then also all file [handles] will be closed, so that’s neither an issue, only programs that do not hit that end in a timely manner.

HOWEVER, at that end the file goes out of scope, and a destructor in e.g. C++ would close it. But in a language like Julia with garbage collection (GC), or e.g. Java, it doesn’t happen eagerly, only when the GC triggers the finalizer.

GC is very good for cleaning up memory, but less good for other resources like files. You still have finalizers for that, but they can be triggered after an extensive amount of time. You could do GC.gc() after that end in the program using the package.

I’m very unclear on why GC.gc() is appropriate in the package itself, because the `end has not been reached yet? Or how this can relate to any possible LibUV bug?

TimG · October 4, 2024, 5:56pm

Thanks for the helpful comments. I was unclear that the finalizer only gets called by the GC, which was fairly important information!

I only realized today that XLSX.jl had dependencies on both ZipFile.jl (for reading) and ZipArchives.jl (for writing). I’ve now completely replaced each remaining use of ZipFile with ZipArchives.

In doing so, I have also removed whatever left an open file lying around, so now everything works as it should without the GC call.

As you were suggesting from the outset @Palli, @nhz2 the libuv bug was nothing of the sort, but merely the manifestation of something in XLSX.jl itself, now (hopefully) rectified.