Using logging module in gevent application

[Рушан Шаймарданов]

I have an application based on gevent. It uses custom logger to log errors to slack channel. The problem is that with this logger enabled, application works about 4 times slower. To demonstrate this, I wrote simple script

    import gevent.monkey
    gevent.monkey.patch_all()
    import gevent.pool
    from functools import partial
    import logging
    import time
    import urllib2
    import urllib




    def send_to_slack(token, channel, username, text):
        data = {
            'token': token,
            'text': text,
            'channel': channel,
            'username': username
        }
        for k, v in data.items():
            data[k] = unicode(v).encode('utf-8')
        req = urllib2.Request('https://slack.com/api/chat.postMessage',
                          urllib.urlencode(data))
        resp = urllib2.urlopen(req)


    class SlackHandler(logging.Handler):


        def __init__(self, token, channel, username):
            super(SlackHandler, self).__init__()
            self.token = token
            self.channel = channel
            self.username = username


        def emit(self, record):
            send_to_slack(
                self.token,
                self.channel,
                self.username,
                self.format(record)
            )


    logger = logging.getLogger(__name__)
    h = SlackHandler('mytoken', '#mychan', 'server-logs')
    h.setLevel(logging.ERROR)


    logger.addHandler(h)


    send = partial(send_to_slack, 'mytoken',
               '#mychan', 'server-logs')




    pool = gevent.pool.Pool(10)


    text = ['text']*10


    start = time.time()
    pool.map(logger.error, text)
    print time.time() - start


    start = time.time()
    pool.map(send, text)
    print time.time() - start

The result was:

    4.66483712196
    0.50646686554

so, sending messages using logging module is 10 times slower then sending them directly. Seems like logging module is not monkeypatched by gevent correctly, or so.

My question is: how to properly use logging module in gevent applications?

[AM]

If you time just the send_to_slack inside the emit what sort of times do
you get?

AM

On 05/31/2016 11:56 PM, Рушан Шаймарданов wrote:
> I have an application based on gevent. It uses custom logger to log
> errors to slack channel. The problem is that with this logger enabled,
> application works about 4 times slower. To demonstrate this, I wrote
> simple script
>
> |
> importgevent.monkey
> gevent.monkey.patch_all()
> importgevent.pool
> fromfunctools importpartial
> importlogging
> importtime
> importurllib2
> importurllib
>
>
>
>
> defsend_to_slack(token,channel,username,text):
> data ={
> 'token':token,
> 'text':text,
> 'channel':channel,
> 'username':username
> }
> fork,v indata.items():
> data[k]=unicode(v).encode('utf-8')

> req =urllib2.Request('https://slack.com/api/chat.postMessage',

> urllib.urlencode(data))
> resp =urllib2.urlopen(req)
>
>
> classSlackHandler(logging.Handler):
>
>
> def__init__(self,token,channel,username):
> super(SlackHandler,self).__init__()
> self.token =token
> self.channel =channel
> self.username =username
>
>
> defemit(self,record):
> send_to_slack(
> self.token,
> self.channel,
> self.username,
> self.format(record)
> )
>
>
> logger =logging.getLogger(__name__)

> h =SlackHandler('mytoken','#mychan','server-logs')
> h.setLevel(logging.ERROR)
>
>
> logger.addHandler(h)
>
>
> send =partial(send_to_slack,'mytoken',

> '#mychan','server-logs')
>
>
>
>
> pool =gevent.pool.Pool(10)
>
>
> text =['text']*10
>
>
> start =time.time()
> pool.map(logger.error,text)
> printtime.time()-start
>
>
> start =time.time()
> pool.map(send,text)
> printtime.time()-start
>
> |
>
>
> The result was:
>
> |
> 4.66483712196
> 0.50646686554
> |
>
>
> so, sending messages using logging module is 10 times slower then
> sending them directly. Seems like logging module is not monkeypatched by
> gevent correctly, or so.
>
> My question is: how to properly use logging module in gevent applications?
>

> --
> You received this message because you are subscribed to the Google
> Groups "gevent: coroutine-based Python network library" group.
> To unsubscribe from this group and stop receiving emails from it, send
> an email to gevent+un...@googlegroups.com
> <mailto:gevent+un...@googlegroups.com>.
> For more options, visit https://groups.google.com/d/optout.

[Рушан Шаймарданов]

0.693855047226

0.549385070801

0.574470996857

0.527421951294

0.530997037888

0.526073217392

0.927090883255

0.785480976105

0.554019212723

0.834668159485

# Summary

6.52160906792

0.819799184799

[Daniel Bradburn]

What do you expect gevent should be patching in the logging module? As far as I can tell there isn't really anything special going on there wouldn't already be patched by patch_all

I think the difference in timings can probably be explained by the fact that when you call logging.error there is quite a bit going on behind the scenes that you don't get when you call your function directly, for example see the following notebook which shows the dramatic difference in timing when calling logging.error vs sys.stderr.write

https://github.com/moagstar/notebooks/blob/master/logging%20timeit.ipynb

When sending through logging you have the checking of log level, creation of log record, routing to the various handlers etc. So it's probably to be expected that these calls are slower, whether or not they should be 10x slower I can't say.

Maybe you can setup a simple test sending messages to slack through the logging module with and without gevent and see if you see any difference.

--

You received this message because you are subscribed to the Google Groups "gevent: coroutine-based Python network library" group.

To unsubscribe from this group and stop receiving emails from it, send an email to gevent+un...@googlegroups.com.

[Рушан Шаймарданов]

Hello Daniel. Thank you for reply.

I measured time taken by single calls to send and logger.error and they are almost the same:

0.491536855698

0.469630002975

So, I still think it's strange that sending 10 messages with gevent 10 times slower with logging module.

I also don't understand what you mean by testing logging module without gevent. Do you mean 10 synchronous calls  or using threading module?

Rushan

[Jason Madden]

It's important to remember that by default `logging.Handler.handle` acquires a per-instance lock around the call to `logging.Handler.emit`. So when you write `pool.map(logger.error, text)`, ultimately those calls to `send_to_slack` are effectively forced to be sequential; whereas when you write `pool.map(send,text)` parallelism can be exploited. So it's no surprise that making 10 sequential calls (via logger.error) takes about 10 times as making a single call.

You can override `logging.Handler.createLock` to avoid creating a lock in your Handler subclass.

[Рушан Шаймарданов]

Thank you, Jason.

I tried to override handle in my handler without locking and as a result, logging.error takes almost equal time as plain send does!

Rushan