<div dir="ltr">Hi David.<div><br></div><div>I planned to create a detailed bug-report at hslogger's issues to start investigation there (as a better place) on Monday, but since I have code prepared already, it's easy to share it right now: <a href="https://gist.github.com/k-bx/ccf6fd1c73680c8a4345">https://gist.github.com/k-bx/ccf6fd1c73680c8a4345</a></div><div><br></div><div>I'm launching it as:</div><div><br></div><div>    time ./dist/build/seq/seq &> /dev/null</div><div><br></div><div>We don't use syslog driver, instead we have a separate file-to-syslog worker to decouple these components.</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Sun, Apr 26, 2015 at 12:08 AM, David Turner <span dir="ltr"><<a href="mailto:dct25-561bs@mythic-beasts.com" target="_blank">dct25-561bs@mythic-beasts.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi,<br>
<br>
I've had a look at this as we use hslogger too, so I'm keen to avoid<br>
this kind of performance issue. I threw a quick Criterion benchmark<br>
together:<br>
<br>
<a href="https://gist.github.com/DaveCTurner/f977123b4498c4c64569" target="_blank">https://gist.github.com/DaveCTurner/f977123b4498c4c64569</a><br>
<br>
The headline result on my test machine are that each log call takes<br>
~540us, so 2000 should take about a second. Would be interested if you<br>
could run the same benchmark on your setup as it's possible that<br>
there's something else downstream that's causing you a problem.<br>
<br>
A couple of things that might be worth bearing in mind: if you're<br>
talking to syslog over /dev/log then that can block if the log daemon<br>
falls behind: unix datagram sockets don't drop datagrams when they're<br>
congested. If the /dev/log test is slow but the UDP test is fast then<br>
it could be that your syslog can't handle the load.<br>
<br>
I'm using rsyslogd and have enabled the feature that combines<br>
identical messages, so this test doesn't generate much disk IO and it<br>
keeps up easily, so the UDP and /dev/log tests run about equally fast<br>
for me. Is your syslog writing out every message? It may be flushing<br>
to disk after every message too, which would be terribly slow.<br>
<br>
If you're not logging to syslog, what's your hslogger config?<br>
<br>
Cheers,<br>
<br>
David<br>
<div class="HOEnZb"><div class="h5"><br>
<br>
On 24 April 2015 at 20:25, Kostiantyn Rybnikov <<a href="mailto:k-bx@k-bx.com">k-bx@k-bx.com</a>> wrote:<br>
> An update for everyone interested (and not). Turned out it's neither GHC<br>
> RTS, Snap or networking issues, it's hslogger being very slow. I thought<br>
> it's slow when used concurrently, but just did a test when it writes 2000<br>
> 5kb messages sequentially and that finishes in 111 seconds (while minimal<br>
> program that writes same 2000 messages finishes in 0.12s).<br>
><br>
> I hope I'll have a chance to investigate why hslogger is so slow in future,<br>
> but meanwhile will just remove logging.<br>
><br>
> On Thu, Apr 23, 2015 at 4:08 PM, Kostiantyn Rybnikov <<a href="mailto:k-bx@k-bx.com">k-bx@k-bx.com</a>> wrote:<br>
>><br>
>> All right, good news!<br>
>><br>
>> After adding ekg, gathering its data via bosun and seeing nothing useful I<br>
>> actually figured out that I could try harder to reproduce issue by myself<br>
>> instead of waiting for users to do that. And I succeeded! :)<br>
>><br>
>> So, after launching 20 infinite curl loops to that handler's url I was<br>
>> quickly able to reproduce the issue, so the task seems clear now: keep<br>
>> reducing the code, reproduce locally, possibly without external services<br>
>> etc. I'll write up after I get to something.<br>
>><br>
>> Thanks.<br>
>><br>
>> On Wed, Apr 22, 2015 at 11:09 PM, Gregory Collins<br>
>> <<a href="mailto:greg@gregorycollins.net">greg@gregorycollins.net</a>> wrote:<br>
>>><br>
>>> Maybe but it would be helpful to rule the scenario out. Johan's ekg<br>
>>> library is also useful, it exports a webserver on a different port that you<br>
>>> can use to track metrics like gc times, etc.<br>
>>><br>
>>> Other options for further debugging include gathering strace logs from<br>
>>> the binary. You'll have to do some data gathering to narrow down the cause<br>
>>> unfortunately -- http client? your code? Snap server? GHC event manager<br>
>>> (System.timeout is implemented here)? GC? etc<br>
>>><br>
>>> G<br>
>>><br>
>>> On Wed, Apr 22, 2015 at 10:14 AM, Kostiantyn Rybnikov <<a href="mailto:k-bx@k-bx.com">k-bx@k-bx.com</a>><br>
>>> wrote:<br>
>>>><br>
>>>> Gregory,<br>
>>>><br>
>>>> Servers are far from being highly-overloaded, since they're currently<br>
>>>> under a much less load they used to be. Memory consumption is stable and<br>
>>>> low, and there's a lot of free RAM also.<br>
>>>><br>
>>>> Would you say that given these factors this scenario is unlikely?<br>
>>>><br>
>>>> On Wed, Apr 22, 2015 at 7:56 PM, Gregory Collins<br>
>>>> <<a href="mailto:greg@gregorycollins.net">greg@gregorycollins.net</a>> wrote:<br>
>>>>><br>
>>>>> Given your gist, the timeout on your requests is set to a half-second<br>
>>>>> so it's conceivable that a highly-loaded server might have GC pause times<br>
>>>>> approaching that long. Smells to me like a classic Haskell memory leak<br>
>>>>> (that's why the problem occurs after the server has been up for a while):<br>
>>>>> run your program with the heap profiler, and audit any shared<br>
>>>>> tables/IORefs/MVars to make sure you are not building up thunks there.<br>
>>>>><br>
>>>>> Greg<br>
>>>>><br>
>>>>> On Wed, Apr 22, 2015 at 9:14 AM, Kostiantyn Rybnikov <<a href="mailto:k-bx@k-bx.com">k-bx@k-bx.com</a>><br>
>>>>> wrote:<br>
>>>>>><br>
>>>>>> Hi!<br>
>>>>>><br>
>>>>>> Our company's main commercial product is a Snap-based web app which we<br>
>>>>>> compile with GHC 7.8.4. It works on four app-servers currently load-balanced<br>
>>>>>> behind Haproxy.<br>
>>>>>><br>
>>>>>> I recently implemented a new piece of functionality, which led to<br>
>>>>>> weird behavior which I have no idea how to debug, so I'm asking here for<br>
>>>>>> help and ideas!<br>
>>>>>><br>
>>>>>> The new functionality is this: on specific url-handler, we need to<br>
>>>>>> query n external services concurrently with a timeout, gather and render<br>
>>>>>> results. Easy (in Haskell)!<br>
>>>>>><br>
>>>>>> The implementation looks, as you might imagine, something like this<br>
>>>>>> (sorry for almost-real-haskell, I'm sure I forgot tons of imports and other<br>
>>>>>> things, but I hope everything is clear as-is, if not -- I'll be glad to<br>
>>>>>> update gist to make things more specific):<br>
>>>>>><br>
>>>>>> <a href="https://gist.github.com/k-bx/0cf7035aaf1ad6306e76" target="_blank">https://gist.github.com/k-bx/0cf7035aaf1ad6306e76</a><br>
>>>>>><br>
>>>>>> Now, this works wonderful for some time, and in logs I can see both,<br>
>>>>>> successful fetches of external-content, and also lots of timeouts from our<br>
>>>>>> external providers. Life is good.<br>
>>>>>><br>
>>>>>> But! After several days of work (sometimes a day, sometimes couple<br>
>>>>>> days), apps on all 4 servers go crazy. It might take some interval (like 20<br>
>>>>>> minutes) before they're all crazy, so it's not super-synchronous. Now: how<br>
>>>>>> crazy, exactly?<br>
>>>>>><br>
>>>>>> First of all, this endpoint timeouts. Haproxy requests for a response,<br>
>>>>>> and response times out, so they "hang".<br>
>>>>>><br>
>>>>>> Secondly, logs are interesting. If you look at the code from gist once<br>
>>>>>> again, you can see, that some of CandidateProvider's don't actually require<br>
>>>>>> any networking work, so all they do is actually just logging that they're<br>
>>>>>> working (I added this as part of debugging actually) and return pure data.<br>
>>>>>> So what's weird is that they timeout also! Here's how output of our logs<br>
>>>>>> starts to look like after the bug happens:<br>
>>>>>><br>
>>>>>> ```<br>
>>>>>> [2015-04-22 09:56:20] provider: CandidateProvider1<br>
>>>>>> [2015-04-22 09:56:20] provider: CandidateProvider2<br>
>>>>>> [2015-04-22 09:56:21] Got timeout while requesting CandidateProvider1<br>
>>>>>> [2015-04-22 09:56:21] Got timeout while requesting CandidateProvider2<br>
>>>>>> [2015-04-22 09:56:22] provider: CandidateProvider1<br>
>>>>>> [2015-04-22 09:56:22] provider: CandidateProvider2<br>
>>>>>> [2015-04-22 09:56:23] Got timeout while requesting CandidateProvider1<br>
>>>>>> [2015-04-22 09:56:23] Got timeout while requesting CandidateProvider2<br>
>>>>>> ... and so on<br>
>>>>>> ```<br>
>>>>>><br>
>>>>>> What's also weird is that, even after timeout is logged, the string<br>
>>>>>> ""Got responses!" never gets logged also! So hanging happens somewhere<br>
>>>>>> in-between.<br>
>>>>>><br>
>>>>>> I have to say I'm sorry that I don't have strace output now, I'll have<br>
>>>>>> to wait until this situation happens once again, but I'll get later to you<br>
>>>>>> with this info.<br>
>>>>>><br>
>>>>>> So, how is this possible that almost-pure code gets timed-out? And why<br>
>>>>>> does it hang afterwards?<br>
>>>>>><br>
>>>>>> CPU and other resource usage is quite low, number of open<br>
>>>>>> file-descriptors also (it seems).<br>
>>>>>><br>
>>>>>> Thanks for all the suggestions in advance!<br>
>>>>>><br>
>>>>>> _______________________________________________<br>
>>>>>> Haskell-Cafe mailing list<br>
>>>>>> <a href="mailto:Haskell-Cafe@haskell.org">Haskell-Cafe@haskell.org</a><br>
>>>>>> <a href="http://mail.haskell.org/cgi-bin/mailman/listinfo/haskell-cafe" target="_blank">http://mail.haskell.org/cgi-bin/mailman/listinfo/haskell-cafe</a><br>
>>>>>><br>
>>>>><br>
>>>>><br>
>>>>><br>
>>>>> --<br>
>>>>> Gregory Collins <<a href="mailto:greg@gregorycollins.net">greg@gregorycollins.net</a>><br>
>>>><br>
>>>><br>
>>><br>
>>><br>
>>><br>
>>> --<br>
>>> Gregory Collins <<a href="mailto:greg@gregorycollins.net">greg@gregorycollins.net</a>><br>
>><br>
>><br>
><br>
><br>
> _______________________________________________<br>
> Haskell-Cafe mailing list<br>
> <a href="mailto:Haskell-Cafe@haskell.org">Haskell-Cafe@haskell.org</a><br>
> <a href="http://mail.haskell.org/cgi-bin/mailman/listinfo/haskell-cafe" target="_blank">http://mail.haskell.org/cgi-bin/mailman/listinfo/haskell-cafe</a><br>
><br>
</div></div></blockquote></div><br></div>