For 1), The previous discussion just concluded that the time to fetch the date is very small. The advantage of always fetching the date is that you can remove the need for a separate date thread [1]. I always think of delays as a code smell and look for other ways of doing things. In this case the docs state: There is no guarantee that the thread will be rescheduled promptly when the delay has expired, but the thread will never continue to run *earlier*than specified. And currently the date thread is set to a delay of one second- it is almost inevitable for it to get time-shifted and then actually end up logging the wrong second (for a second, not that it would matter a lot too most). The real issue is that under high load we don't have a guarantee that time will be updated- if competing against CPU bound threads this implementation would rely on fair scheduling to get the date updated. I think the additional complexity of a separate thread should be justified in a benchmark vs. the simpler solution discussed which Snap now implements [1]. Greg Weber [1]: See how much simpler Snap's logging code is after our discussion: http://hdiff.luite.com/cgit/snap-server/commit/?id=bc9e93afd1504753b5d22a11d... On Thu, Aug 18, 2011 at 6:47 AM, Michael Snoyman wrote:

On Thu, Aug 18, 2011 at 11:21 AM, Kazu Yamamoto wrote:

...

Hello,

Sorry for the delay but I have released wai-logger: http://hackage.haskell.org/package/wai-logger

I provide low level modules and a high level module. Users should use the low level modules. The high level module is designed for Mighttpd which uses the prefork technique.

A sample code is found in its module documentation.

Please use this package and give me feedback. And let's consider how to make this as a WAI middle ware.

--Kazu

_______________________________________________ web-devel mailing list web-devel@haskell.org http://www.haskell.org/mailman/listinfo/web-devel

Looks very good. Two questions:

1. I thought the conclusion of the previous discussion was that updating the time every second via a thread was less efficient than comparing timestamps and updating as necessary. 2. Would it make sense to use a Builder (from blaze-builder) in place of LogStr? Though based on the black magic you have going on under the surface there, I'm guessing you did it this way for a reason ;).

Thanks, Michael

_______________________________________________ web-devel mailing list web-devel@haskell.org http://www.haskell.org/mailman/listinfo/web-devel

Actually, the idea we'd been passing around was having an IORef with both the rendered time and the integral time. Whenever the rendered time is requested, we first compare the stored integral time with the current time. Only if there's a mismatch would we generate a new rendered time. On Fri, Aug 19, 2011 at 9:11 AM, Kazu Yamamoto wrote:

Hello,

...

For 1), The previous discussion just concluded that the time to fetch the date is very small. The advantage of always fetching the date is that you can remove the need for a separate date thread [1]. I always think of delays as a code smell and look for other ways of doing things. In this case the docs state:

The real problem is that the logging date fromat is *a zone time*.  It is a tough job to implement due to a time zone. Data.Time can produce it but it is too slow for our purpose. This is why wai-logger uses Data.Time just once every second.

I looked the code of snap-core and it fixes this problem using C's strftime.

OK. I will try to call the following C code everytime without the date thread and compare it with the original.

--Kazu

#include #include

main () {  time_t timer;  struct tm *date;  char str[40];

 timer = time(NULL);  date = localtime(&timer);  strftime(str, 40, "%d/%b/%Y:%H:%M:%S %z", date);  printf("%s\n", str); }

_______________________________________________ web-devel mailing list web-devel@haskell.org http://www.haskell.org/mailman/listinfo/web-devel

Hello, I have implemented data-thread-less version: https://github.com/kazu-yamamoto/wai-logger/blob/master/Network/Wai/Logger/D... Since its performance is almost the same as the original, I have merged it into master. Tommorrow I will try using C's localtime() and strftime() as Snap does. --Kazu

...

Actually, the idea we'd been passing around was having an IORef with both the rendered time and the integral time. Whenever the rendered time is requested, we first compare the stored integral time with the current time. Only if there's a mismatch would we generate a new rendered time.

Thank you for explanation. Now I understand the idea passed around and what snap is doing. OK. I will implement this idea in wai-logger.

--Kazu

_______________________________________________ web-devel mailing list web-devel@haskell.org http://www.haskell.org/mailman/listinfo/web-devel

Hi Kazu, 2011/8/19 Kazu Yamamoto :

Hello,

...

2. Would it make sense to use a Builder (from blaze-builder) in place of LogStr? Though based on the black magic you have going on under the surface there, I'm guessing you did it this way for a reason ;).

I have implemented a Builder version:

       git://github.com/kazu-yamamoto/wai-logger.git        branch: blaze

Attached code shows how to use this version.

Please read the implementation of hPutBuilder:

       https://github.com/kazu-yamamoto/wai-logger/blob/blaze/Network/Wai/Logger/IO...

In this version, I guess that intermediate ByteString is not fused, so one unnecessary intermediate ByteString is created with toByteString. Thus, this version is slower than the original. Since I'm a beginner of blaze-builder, I don't know how we can directly copy Builder to Handle's buffer. Suggestions would be appreciated.

--Kazu

{-# LANGUAGE OverloadedStrings #-}

module Main where

import Blaze.ByteString.Builder (fromByteString) import Control.Monad.IO.Class (liftIO) import Data.ByteString.Char8 import Network.HTTP.Types (status200) import Network.Wai import Network.Wai.Handler.Warp import Network.Wai.Logger import System.IO

main :: IO () main = do    initHandle stdout -- set blockBuffering    dref <- dateInit    run 3000 $ logApp dref

logApp :: DateRef -> Application logApp dref req = do    date <- liftIO $ getDate dref    let status = status200        len = 4    liftIO $ hPutBuilder stdout $ apacheFormatBuilder date req status (Just len)    liftIO $ hFlush stdout  -- delete here to see if block buffered    return $ ResponseBuilder status                             [("Content-Type", "text/plain")                             ,("Content-Length", pack (show len))]           $ fromByteString "PONG"

I should have read this mail before answering the other one. There are two problems with this benchmark: 1. toByteString :: Builder -> S.ByteString is more expensive than toLazyByteString :: Builder -> L.ByteString because it first generates a chunked output, which is then packed. This function was a big mistake to put into blaze-builder, as people expect performance that doesn't exist. 2. When comparing the speed of the two solutions, I would go for an isolated benchmark that measures the encoding time only. As far as I understand your setup above, you're also measuring quite some server-overhead and do not allow the builders to amortize the buffer allocation time, as very short responses are generated. See my copy of the other mail for more explanations: -- begin: copy from mail on the other thread -- Hi Kazu, 2011/8/19 Kazu Yamamoto :

Hello Simon,

...

if you're going for such a solution, then why not use difference lists or even better bytestring builders as your representation of the not-yet-flushed logging journal? Bytestring builders (from the blaze-builder library) support a fast append and fast serialization from a number of formats to bytestring.

Difference lists are not necessary at this moment because a list is generated at once in the apacheFormat:

http://hackage.haskell.org/packages/archive/wai-logger/0.0.0/doc/html/src/Ne...

If my understanding is correct, blaze-builder does not help hPutLogStr. What I want to do is directly copy ByteString or List to *Handle's buffer*.

http://hackage.haskell.org/packages/archive/wai-logger/0.0.0/doc/html/src/Ne...

I see. Currently, builders cannot be executed directly on a Handle's buffer. This is functionality I wanted to have for a long time, but have not gotten around to implement it. Using bytestring builders you could avoid creating the intermediate [LogStr] list. You should get a performance benefit, when describing your log-message directly as a mapping to a builder and executing this builder on the handle's buffer, as this avoids the indirections from the list- and the LogStr-cells. Copying the byteStrings directly also works for builders using the 'copyByteString' function. You would get a further performance benefit, if you could avoid creating intermediate String values. For example, the new builder in the bytestring library provides functions for the decimal encoding of numbers directly into the output buffer using a fast C-implementation. The development repository of the new bytestring builders is available here [1]. Its API is finished, benchmarks look good, and a documentation draft exists. Hence, it would be cheap to give it a go and see how fast you could produce the log-messages using the new bytestring builders. I'd use criterion to compare mapM_ yourLogMessageWriter logMessageList against whnf (L.length . toLazyByteString . mconcat . map builderLogMessageWriter) logMessageList where logMessageList :: [(ZonedDate, Request, Status, Maybe Integer)] logMessageList = replicate 10000 ( your-message-params) This should be a fair comparison, as both implementations work on similarly large buffers. If that shows that builders are beneficial, then we can think about implementing output on a Handle's buffer directly. best regards, Simon PS: The new bytestring builder will very likely be released with the next GHC in November. [1] https://github.com/meiersi/bytestring -- end: copy -- best regards, Simon