Would like to add file appender since spit appender takes more time

[nvseenu]

Hi,

"spit-appender" opens and closes the file for each log message. so does "rolling-appender". Frequent opening and closing of a log file consumes more time, than writing messages into the file.

Do we have any efficient file appender for timbre logging library or do we need to write one? i am interested to write such one.

I just tested this use case with below code. I see spit-appender consumes 800 ms and "opening-file-once" approach consumes 20 ms approximately.

(def data (-> (repeat 200 "x")
              str/join))

(def spit-file #(spit "spit-log.txt" %1 :append true))

(defn spit-test[data n]
  (doseq [_ (range n)]
    (spit-file data)))


(defn file-test[data n]
  (with-open [w (io/writer "file-test.log" :append true)]
    (doseq [_ (range n)]
      (.write w data))))

(print  "spit-appender :")
(time (spit-test data 1000))
(print  "file-appender:")
(time (file-test data 1000))

Thanks.

[ptaoussanis]

Hi there, PR welcome if you have a specific strategy in mind that'd help.

Please keep in mind that it wouldn't be feasible to just keep the file permanently open as in your benchmark above.

[nvseenu]

Thank you. Let me start work on this.

My approach would be as follows

1. Create/ open the file when we configure appenders
2. keep it open during logging.
   2.1) Any error, file will be closed and reopened.
3. Close the file when logging has been stopped / shutdown. I need to see if we have any function to give a hook to close the opened file.

[ptaoussanis]

3. Close the file when logging has been stopped / shutdown. I need to see if we have any function to give a hook to close the opened file.

This is going to be the difficult one. How will you know when "logging has stopped"?

The only obvious approach I can think of is to open the file, and start a recurring timer that checks every n seconds if there's been a write. If there hasn't, close the file.

That'd work, but would involve more moving parts than I think this warrants.

Keep in mind that even the current implementation can write 1000 lines in ~20ms. And if one needed more for bursting, there's the :async? option.

In any case, happy to take a look at a PR if you feel you have a reasonable solution in mind. Cheers! :-)

[nvseenu]

The approach i described needs a function like taoensso.timbre/stop!. It will be a hook to release any resources held by appenders.

I quickly looked at the logback manual, it has a method "stop" to release the resources.

import org.sflf4j.LoggerFactory;
import ch.qos.logback.classic.LoggerContext;
...

// assume SLF4J is bound to logback-classic in the current environment
LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
loggerContext.stop();

[ptaoussanis]

When would the stop fn be called, and by whom?

[nvseenu]

Generally it should be called when the web server is down through ServletContextListener#contextDestroyed. For standalone program, we need to call it manually.

Another approach is adding shutdownhook to Runtime class.
http://stackoverflow.com/questions/17400136/how-to-log-within-shutdown-hooks-with-log4j2
In this way, we don't need to call stop function outside of timbre namespace.

[ptaoussanis]

I'll be honest, I'm not very keen on adopting a new manual shutdown process just for this.

For one, the level of complexity would be even greater than the timeout approach I described above and discounted for being unnecessarily complex.

Before we continue; may I ask if it's a real requirement that you write >1000 entries per second on one device? We can make this go faster, but it's simple as it is and usually fast enough; is this really a bottleneck in a real-world application?

[nvseenu]

Thank you for your reply. No, i don't have any real requirement. While I was reading timbre logging code base, I happened to see "spit" function used for file writing. It looked different to me as other logging framework like log4j and logback deals with file writing differently.

Then I just wanted to know how much time difference it would be "spit" and "open-file-once" approach. The difference was approximately 50%. That is where all these things started.

[ptaoussanis]

Okay, gotcha - thanks for clarifying.

Opening and closing on each write is much slower than holding the file open. But the absolute cost is relatively insignificant either way in most cases, especially for a couple-line little appender that no one would really want to use for a major deployment anyway.

If you've got an application that's putting out more than 40k log entries per second, in all likelihood you're anyway going to want to be writing to a proper DB or other software that's going to manage stuff like flushing, rotations, etc.

This little appender's mostly just for simple applications that don't do an awful lot of logging. Like I say, we can certainly make if faster - but the cost would be extra complexity and engineering time - which I think probably wouldn't be worth it in this case.

Does that make sense / seem reasonable?

[nvseenu]

IMHO, Big applications are relying on logs first. Generally Each server
will be accompanied by log indexer tool. It constantly reads the log
messages in some periodic intervals and sends the logs to centralized log
server like Elastic Search, Splunk. Databases are not much used to store
logging data since connecting to db is slower than writing into log files.
Also db maintenance is harder than log files maintenance.

I am ok with "spit" approach for smaller applications. But, Don't you have
a plan to use/extend timbre logging for big applications?

Thanks Again.

On Fri, Jul 1, 2016 at 4:31 PM, Peter Taoussanis [email protected]
wrote:

Okay, gotcha - thanks for clarifying.

Opening and closing on each write is much slower than holding the file
open. But the absolute cost is relatively insignificant either way in most
cases, especially for a couple-line little appender that no one would
really want to use for a major deployment anyway.

If you've got an application that's putting out more than 40k log entries
per second, in all likelihood you're anyway going to want to be writing to
a proper DB or other software that's going to manage stuff like flushing,
rotations, etc.

This little appender's mostly just for simple applications that don't do
an awful lot of logging. Like I say, we can certainly make if faster - but
the cost would be extra complexity and engineering time - which I think
probably wouldn't be worth it in this case.

Does that make sense / seem reasonable?

—
You are receiving this because you authored the thread.
Reply to this email directly, view it on GitHub
#174 (comment),
or mute the thread
https://github.com/notifications/unsubscribe/AEwX8UsNk0sSEELGkz-z7AALGN_AjCyKks5qRPNwgaJpZM4JCOJi
.

[ptaoussanis]

Timbre's well suited to large applications. This particular appender is described as a "simple spit appender", and is there mostly as an example or for folks who don't have more demanding needs (maybe 80% of users in practice).

More sophisticated users will want to use a different appender that fits their particular needs and environment. In most cases that'll mean an appender that coordinates with a robust, external logging system. Timbre's primary job is as a dispatcher; i.e. to interface between Clojure code and your logging targets. Appenders are the glue in this scenario; and the more sophisticated your needs, the more likely you're going to want a custom appender. They're just functions, and not hard to write - that Timbre comes out-the-box with any appenders at all, is mostly for convenience.

Since the motivations behind this issue are hypothetical and I'm juggling a lot of urgent work atm, unfortunately going to need to bow out of further correspondence on this. Please feel free to close if you're satisfied. Otherwise always happy to take a look at a specific PR/s if you'd like to submit.

If you do feel like exploring this further, I'd encourage you to really consider what the full range of approaches might be to something like this and what their tradeoffs are.

Cheers! :-)

[nvseenu]

I agree with there is no much can be done on small "spit" appender. But if we need to include better appender for the heavy logging use case, there is some support needed from timbre library side like "shutdownHook". Without such support, appender has no way to know when it can close / free the resources.

We can have a timer approach, But still we need to know when the timer can be stopped.
Anyway, Let me try something by creating new file appender and come back to you, instead of talking more on this.

[nvseenu]

Sent a pull request

Please review and let me know your feedback.

[ptaoussanis]

Sure. Please note that it may take me a week or more to get back to you, have my hands pretty full atm.

[nvseenu]

Thank you for the prompt reply

[ptaoussanis]

No problem, thanks for the PR :-)

[ptaoussanis]

Discussion at #181.