Upgrade from 2.6.3 to any later kills shutdown time

[vesse]

Hi,

I updated a project to use the latest timbre and noticed that running lein do drop, migrate suddenly took 9 times more time than earlier.

I worked my way downwards and found out that this behavior starts occurring from version 2.7.0. With 2.6.x things work just fine. I did reproduce this behavior multiple times.

For some reason when a task is done and it prints its last message on screen it takes ages for the process to end (about 2 minutes). Any ideas what could be wrong?

[ptaoussanis]

Hi Vesa,

Thanks a lot for narrowing down on the version - that's really helpful. I suspect it might have something to do with a change to the get-hostname fn introduced in 2.7.0.

Will try look into it later today and get back to you. Cheers! :-)

[ptaoussanis]

BTW just to confirm - is this the lein migrate you're talking about?: https://github.com/pjstadig/migratus

[vesse]

No, it's drift. But happens also with the drop task which is custom made.

[vesse]

I extracted the get-hostname code and ran it and can now say the problem is indeed related to that:

(defn memoize-ttl [ttl-ms f]
  (let [cache (atom {})]
    (fn [& args]
      (let [{:keys [time-cached d-result]} (@cache args)
            now (System/currentTimeMillis)]

        (if (and time-cached (< (- now time-cached) ttl-ms))
          @d-result
          (let [d-result (delay (apply f args))]
            (swap! cache assoc args {:time-cached now :d-result d-result})
            @d-result))))))

(def get-hostname
  (memoize-ttl 60000
    (fn []
      (let [p (promise)]
        (future ; Android doesn't like this on the main thread
          (deliver p
            (try (.. java.net.InetAddress getLocalHost getHostName)
                 (catch java.net.UnknownHostException _
                   "UnknownHost"))))
        @p))))

(defn drop-db! []
  (->
    (get-hostname)
    (prn)))

This quickly prints the hostname and then takes a minute to exit.

[ptaoussanis]

Hi Vessa, sorry for not getting back to you - am a little swamped atm. Appreciate the follow-up.

To clarify: you're saying the print happens quickly, it's just the shutdown that then takes long?

Could you try an alternative on your end?

  @(future
    (try (.. java.net.InetAddress getLocalHost getHostName)
         (catch java.net.UnknownHostException _
           "UnknownHost")))

Does it help if you call (shutdown-agents) in your app's teardown code?

[ptaoussanis]

Another one to try:

(->
 (future ; Android doesn't like this on the main thread
   (try (.. java.net.InetAddress getLocalHost getHostName)
        (catch java.net.UnknownHostException _
          "UnknownHost")))
 (deref 5000 "UnknownHost"))

You can just stick that anywhere in your code and see if it hits your shutdown time.

[vesse]

Hi,

No worries, I'm not in a hurry since the old version works just fine. And yes, the print happens quickly.

If I understood correctly you wanted me to try this:

(def get-hostname
  (memoize-ttl 60000
    (fn []
      @(future
         (try (.. java.net.InetAddress getLocalHost getHostName)
           (catch java.net.UnknownHostException _
             "UnknownHost"))))))

and this:

(defn my-task []
  (->
    (future ; Android doesn't like this on the main thread
      (try (.. java.net.InetAddress getLocalHost getHostName)
        (catch java.net.UnknownHostException _
          "UnknownHost")))
    (deref 5000 "UnknownHost")
    (prn)))

Neither works any better. Calling (shutdown-agents) does help.

[ptaoussanis]

Yeah, that's right - thanks.

Calling (shutdown-agents) does help.

As in helps a little, or completely eliminates the shutdown delay?

[vesse]

Eliminates it completely.

[ptaoussanis]

Hmm, this is a bit tricky.

My understanding's a little rough on the details but basically: using the future inits a Clojure thread pool which can negatively impact shutdown time if you don't have a call to shutdown-agents in your app's termination routine.

You can probably see the same behaviour by adding something simple like @(future (Thread/sleep 2000)) anywhere in your app.

I do recall that there was some talk on the dev list at some point about possibly making this (semi?) automatic - but I don't recall what came of that and can't find the discussion now.

So a short-term solution to work around this:

(defn destroy! [] <... other stuff> (shutdown-agents))
(.addShutdownHook (Runtime/getRuntime) (Thread. ^Runnable destroy!)) 

That'll make sure Clojure's thread pool gets closed on app shutdown.

I'm not super happy about suggesting that everyone do that though... will need to do a little digging to find out what the current view is on agent shutdown. Won't have the time for a couple days at least, but I'll keep this issue open and get back to you if I come up with a better long-term solution.

Thanks again for bringing this to my attention and with the assistance debugging. Cheers! :-)

[cloojure]

I love Timbre, but this issue is confusing for new users. Running the demo causes the console to hang for 60 seconds unless either (shutdown-agents) or (System/exit 0) is called.

Scanning the mailing list shows no discussion of switching agents to daemon threads for several years. Is this a dead issue?

Alan

[ptaoussanis]

Hi Alan, not a dead issue at all. Have been too swamped lately to investigate possible alternatives - but I'd be very happy to see a PR or suggestions.

I've got a number of changes queued that I'd like to make for an upcoming Timbre v4 release, so I'll likely look closer at this when I'm doing that work - but no ETA unfortunately. Best bet would be a PR if you're looking to see this resolved ASAP.

Cheers! :-)

[cloojure]

Actually, I had assumed that a change to Clojure itself would be required
(judging from past mailing list posts). Do you think that it can be fixed
in Timbre itself?
Alan

On Fri, Oct 31, 2014 at 12:05 AM, Peter Taoussanis <notifications@github.com

wrote:

Hi Alan, not a dead issue at all. Have been too swamped lately to
investigate possible alternatives - but I'd be very happy to see a PR or
suggestions.

I've got a number of changes queued that I'd like to make for an upcoming
Timbre v4 release, so I'll likely look closer at this when I'm doing that
work - but no ETA unfortunately. Best bet would be a PR if you're looking
to see this resolved ASAP.

Cheers! :-)

—
Reply to this email directly or view it on GitHub
#61 (comment).

[ptaoussanis]

Closing this, looks like there's not much that can be done from Timbre's side. Will just document the issue+workaround for now.