cuDNN loses memory to log messages in Pluto.jl context

[fps]

See: fonsp/Pluto.jl#3183 for context. And also: https://discourse.julialang.org/t/memory-usage-increasing-with-each-epoch/121798/2

Pluto.jl sets up logging in a way such that

Base.CoreLogging.current_logger_for_env(Base.CoreLogging.Debug, :init, CUDA) gives PlutoRunner.PlutoCellLogger...

This in turn causes cuDNN's initialization to setup a message callback with cudnnSetCallback which in turn causes cuDNN.log_messages to grow without bounds when doing things because every single call seems to get logged.

I am not sure who really is to blame here, so I thought I'd open up an issue here as well because I am not familiar at all with Julia's logging/debug eco system.

[maleadt]

I'm not familiar with Pluto's logging, so this will have to be investigated by somebody who is. The logic on CUDA.jl's side is pretty straightforward:

• if debugging is enabled, CUDA.CUDNN's __init__ will enable CUDNN logging:

  CUDA.jl/lib/cudnn/src/cuDNN.jl

  Lines 190 to 192 in 719b4c4

  	callback = @cfunction(log_message, Nothing,
  	(cudnnSeverity_t, Ptr{Cvoid}, Ptr{cudnnDebug_t}, Ptr{UInt8}))
  	cudnnSetCallback(typemax(UInt32), log_cond[], callback)

• each generated log message calls log_message via a @cfunction callback
• log_message processes the message and puts it in a buffer, while notifying an AsyncCondition:

  CUDA.jl/lib/cudnn/src/cuDNN.jl

  Lines 136 to 140 in 719b4c4

  	# print asynchronously
  	Base.@lock log_lock begin
  	push!(log_messages, (; sev, dbg, str))
  	end
  	ccall(:uv_async_send, Cint, (Ptr{Cvoid},), udata)

• that AsyncCondition pops a message from the buffer and renders it:

  CUDA.jl/lib/cudnn/src/cuDNN.jl

  Lines 185 to 188 in 719b4c4

  	log_cond[] = Base.AsyncCondition() do async_cond
  	message = Base.@lock log_lock popfirst!(log_messages)
  	_log_message(message...)
  	end

  CUDA.jl/lib/cudnn/src/cuDNN.jl

  Lines 145 to 158 in 719b4c4

  	function _log_message(sev, dbg, str)
  	lines = split(str, '\0')
  	msg = join(lines, '\n')
  	if sev == CUDNN_SEV_INFO
  	@debug msg
  	elseif sev == CUDNN_SEV_WARNING
  	@warn msg
  	elseif sev == CUDNN_SEV_ERROR
  	@error msg
  	elseif sev == CUDNN_SEV_FATAL
  	error(msg)
  	end
  	return
  	end

[fps]

Hmm, OK, I guess there are two separate problems here:

1. Pluto unconditionally (?) setting up a debug logger. This might be unnecessary @fonsp?
2. The AsyncCondition not firing and therefore not emptying the message buffer.

[maleadt]

Doing this by default is definitely not expected. It's debug logging, after all, not simply increased verbosity.

[fps]

Re: 1. I guess it has been set up this way so that debug macros work in cell code. Hmmm, maybe the debug level logger shouldn't be active during imports though.

Re: 2. It seems cuDNN triggers the async condition by way of a direct library call to libuv. Is that an internal julia thing? I wonder what assumption is broken here.

[maleadt]

Re: 2. It seems cuDNN triggers the async condition by way of a direct library call to libuv. Is that an internal julia thing? I wonder what assumption is broken here.

This is a typical pattern to work with callbacks from foreign threads: https://docs.julialang.org/en/v1/manual/calling-c-and-fortran-code/#Thread-safety

Nowadays it's possible to call back into Julia from non-Julia managed threads, but for the sake of supporting older versions of Julia we still do it the old way.

[fps]

Thanks for the link and explanation. You're right, everything looks quite in order from the cuDNN side as far as I can tell. I guess I'll have to find out a bit more about how julia implements its event loops and how Pluto "messes" with them. Thanks again!

[maleadt]

No problem. Feel free to open a new issue if this does still turn out to be an issue here, or if we can improve things.