Re: Ref-strings in logging messages (was: Performance issue with CPython 3.10 + Cython)

[Barry Scott]

> On 8 Oct 2022, at 11:50, Weatherby,Gerard  wrote:
> 
> Logging does support passing a callable, if indirectly. It only calls __str__ 
> on the object passed if debugging is enabled.
>  
> class Defer:
> 
> def __init__(self,fn):
> self.fn = fn
> 
> def __str__(self):
> return self.fn()
> 
> def some_expensive_function():
> return "hello"
> 
> logging.basicConfig()
> logging.debug(Defer(some_expensive_function))

Oh what a clever hack. Took a few minutes of code reading to see why this works.
You are exploiting the str(msg) that is in class LogRecords getMessage().

```
def getMessage(self):
"""
Return the message for this LogRecord.

Return the message for this LogRecord after merging any user-supplied
arguments with the message.
"""
msg = str(self.msg)
if self.args:
msg = msg % self.args
return msg
```

Barry


>  
>  
> From: Python-list  > on behalf of 
> Barry mailto:ba...@barrys-emacs.org>>
> Date: Friday, October 7, 2022 at 1:30 PM
> To: MRAB mailto:pyt...@mrabarnett.plus.com>>
> Cc: python-list@python.org  
> mailto:python-list@python.org>>
> Subject: Re: Ref-strings in logging messages (was: Performance issue with 
> CPython 3.10 + Cython)
> 
> *** Attention: This is an external email. Use caution responding, opening 
> attachments or clicking on links. ***
> 
> > On 7 Oct 2022, at 18:16, MRAB  wrote:
> >
> > On 2022-10-07 16:45, Skip Montanaro wrote:
> >>> On Fri, Oct 7, 2022 at 9:42 AM Andreas Ames 
> >>> 
> >>> wrote:
> >>> 1. The culprit was me. As lazy as I am, I have used f-strings all over the
> >>> place in calls to `logging.logger.debug()` and friends, evaluating all
> >>> arguments regardless of whether the logger was enabled or not.
> >>>
> >> I thought there was some discussion about whether and how to efficiently
> >> admit f-strings to the logging package. I'm guessing that's not gone
> >> anywhere (yet).
> > Letting you pass in a callable to call might help because that you could 
> > use lambda.
> 
> Yep, that’s the obvious way to avoid expensive log data generation.
> Would need logging module to support that use case.
> 
> Barry
> 
> > --
> > https://urldefense.com/v3/__https://mail.python.org/mailman/listinfo/python-list__;!!Cn_UX_p3!mrESxAj9YCHsdtNAfkNiY-Zf6U3WTIqaNrgBmbw1ELlQy51ilob43dD0ONsqvg4a94MEdOdwomgyqfyABbvRnA$
> >  
> > 
> >
> 
> --
> https://urldefense.com/v3/__https://mail.python.org/mailman/listinfo/python-list__;!!Cn_UX_p3!mrESxAj9YCHsdtNAfkNiY-Zf6U3WTIqaNrgBmbw1ELlQy51ilob43dD0ONsqvg4a94MEdOdwomgyqfyABbvRnA$
>  
> 
-- 
https://mail.python.org/mailman/listinfo/python-list

Re: Ref-strings in logging messages (was: Performance issue with CPython 3.10 + Cython)

[Weatherby,Gerard]

Logging does support passing a callable, if indirectly. It only calls __str__ 
on the object passed if debugging is enabled.

class Defer:

def __init__(self,fn):
self.fn = fn

def __str__(self):
return self.fn()

def some_expensive_function():
return "hello"

logging.basicConfig()
logging.debug(Defer(some_expensive_function))


From: Python-list  on 
behalf of Barry 
Date: Friday, October 7, 2022 at 1:30 PM
To: MRAB 
Cc: python-list@python.org 
Subject: Re: Ref-strings in logging messages (was: Performance issue with 
CPython 3.10 + Cython)
*** Attention: This is an external email. Use caution responding, opening 
attachments or clicking on links. ***

> On 7 Oct 2022, at 18:16, MRAB  wrote:
>
> On 2022-10-07 16:45, Skip Montanaro wrote:
>>> On Fri, Oct 7, 2022 at 9:42 AM Andreas Ames 
>>> wrote:
>>> 1. The culprit was me. As lazy as I am, I have used f-strings all over the
>>> place in calls to `logging.logger.debug()` and friends, evaluating all
>>> arguments regardless of whether the logger was enabled or not.
>>>
>> I thought there was some discussion about whether and how to efficiently
>> admit f-strings to the logging package. I'm guessing that's not gone
>> anywhere (yet).
> Letting you pass in a callable to call might help because that you could use 
> lambda.

Yep, that’s the obvious way to avoid expensive log data generation.
Would need logging module to support that use case.

Barry

> --
> https://urldefense.com/v3/__https://mail.python.org/mailman/listinfo/python-list__;!!Cn_UX_p3!mrESxAj9YCHsdtNAfkNiY-Zf6U3WTIqaNrgBmbw1ELlQy51ilob43dD0ONsqvg4a94MEdOdwomgyqfyABbvRnA$
>

--
https://urldefense.com/v3/__https://mail.python.org/mailman/listinfo/python-list__;!!Cn_UX_p3!mrESxAj9YCHsdtNAfkNiY-Zf6U3WTIqaNrgBmbw1ELlQy51ilob43dD0ONsqvg4a94MEdOdwomgyqfyABbvRnA$
-- 
https://mail.python.org/mailman/listinfo/python-list

Re: Ref-strings in logging messages (was: Performance issue with CPython 3.10 + Cython)

[Julian Smith]

On Fri, 7 Oct 2022 18:28:06 +0100
Barry  wrote:

> > On 7 Oct 2022, at 18:16, MRAB  wrote:
> > 
> > On 2022-10-07 16:45, Skip Montanaro wrote:  
> >>> On Fri, Oct 7, 2022 at 9:42 AM Andreas Ames 
> >>> 
> >>> wrote:
> >>> 1. The culprit was me. As lazy as I am, I have used f-strings all over the
> >>> place in calls to `logging.logger.debug()` and friends, evaluating all
> >>> arguments regardless of whether the logger was enabled or not.
> >>>   
> >> I thought there was some discussion about whether and how to efficiently
> >> admit f-strings to the logging package. I'm guessing that's not gone
> >> anywhere (yet).  
> > Letting you pass in a callable to call might help because that you could 
> > use lambda.  
> 
> Yep, that’s the obvious way to avoid expensive log data generation.
> Would need logging module to support that use case.

I have some logging code that uses eval() to evaluate expressions using
locals and globals in a parent stack frame, together with a parser to
find `{...}` items in a string.

I guess this constitutes a (basic) runtime implementation of f-strings.
As such it can avoid expensive evaluation/parsing when disabled, though
it's probably slow when enabled compared to native f-strings. It seems
to work quite well in practise, and also allows one to add some extra
formatting features.

For details see:


https://git.ghostscript.com/?p=mupdf.git;a=blob;f=scripts/jlib.py;h=e85e9f2c4;hb=HEAD#l41

- Jules

-- 
http://op59.net
-- 
https://mail.python.org/mailman/listinfo/python-list

Re: Ref-strings in logging messages (was: Performance issue with CPython 3.10 + Cython)

[Barry]

> On 7 Oct 2022, at 19:09, Weatherby,Gerard  wrote:
> The obvious way to avoid log generation is:
> 
> if logger.isEnableFor(logging.DEBUG):
>logger.debug( expensive processing )
> 
> 
> Of course, having logging alter program flow could lead to hard to debug bugs.

Altered flow is less of an issue the the verbosity of the above.
We discussed ways to improve this pattern a few years ago.
That lead to no changes.

What I have used is a class that defines __bool__ to report if logging is 
enabled and __call__ to log. Then you can do this:

log_debug = logger_from(DEBUG)

log_debug and log_debug(‘expensive %s’ % (complex(),))

Barry

> 
> From: Python-list  on 
> behalf of Barry 
> Date: Friday, October 7, 2022 at 1:30 PM
> To: MRAB 
> Cc: python-list@python.org 
> Subject: Re: Ref-strings in logging messages (was: Performance issue with 
> CPython 3.10 + Cython)
> *** Attention: This is an external email. Use caution responding, opening 
> attachments or clicking on links. ***
> 
>> On 7 Oct 2022, at 18:16, MRAB  wrote:
>> 
>> On 2022-10-07 16:45, Skip Montanaro wrote:
 On Fri, Oct 7, 2022 at 9:42 AM Andreas Ames 
 wrote:
 1. The culprit was me. As lazy as I am, I have used f-strings all over the
 place in calls to `logging.logger.debug()` and friends, evaluating all
 arguments regardless of whether the logger was enabled or not.
>>> I thought there was some discussion about whether and how to efficiently
>>> admit f-strings to the logging package. I'm guessing that's not gone
>>> anywhere (yet).
>> Letting you pass in a callable to call might help because that you could use 
>> lambda.
> 
> Yep, that’s the obvious way to avoid expensive log data generation.
> Would need logging module to support that use case.
> 
> Barry
> 
>> --
>> https://urldefense.com/v3/__https://mail.python.org/mailman/listinfo/python-list__;!!Cn_UX_p3!mrESxAj9YCHsdtNAfkNiY-Zf6U3WTIqaNrgBmbw1ELlQy51ilob43dD0ONsqvg4a94MEdOdwomgyqfyABbvRnA$
> 
> --
> https://urldefense.com/v3/__https://mail.python.org/mailman/listinfo/python-list__;!!Cn_UX_p3!mrESxAj9YCHsdtNAfkNiY-Zf6U3WTIqaNrgBmbw1ELlQy51ilob43dD0ONsqvg4a94MEdOdwomgyqfyABbvRnA$
> -- 
> https://mail.python.org/mailman/listinfo/python-list

-- 
https://mail.python.org/mailman/listinfo/python-list

Re: Ref-strings in logging messages (was: Performance issue with CPython 3.10 + Cython)

[Weatherby,Gerard]

The obvious way to avoid log generation is:

if logger.isEnableFor(logging.DEBUG):
logger.debug( expensive processing )


Of course, having logging alter program flow could lead to hard to debug bugs.

From: Python-list  on 
behalf of Barry 
Date: Friday, October 7, 2022 at 1:30 PM
To: MRAB 
Cc: python-list@python.org 
Subject: Re: Ref-strings in logging messages (was: Performance issue with 
CPython 3.10 + Cython)
*** Attention: This is an external email. Use caution responding, opening 
attachments or clicking on links. ***

> On 7 Oct 2022, at 18:16, MRAB  wrote:
>
> On 2022-10-07 16:45, Skip Montanaro wrote:
>>> On Fri, Oct 7, 2022 at 9:42 AM Andreas Ames 
>>> wrote:
>>> 1. The culprit was me. As lazy as I am, I have used f-strings all over the
>>> place in calls to `logging.logger.debug()` and friends, evaluating all
>>> arguments regardless of whether the logger was enabled or not.
>>>
>> I thought there was some discussion about whether and how to efficiently
>> admit f-strings to the logging package. I'm guessing that's not gone
>> anywhere (yet).
> Letting you pass in a callable to call might help because that you could use 
> lambda.

Yep, that’s the obvious way to avoid expensive log data generation.
Would need logging module to support that use case.

Barry

> --
> https://urldefense.com/v3/__https://mail.python.org/mailman/listinfo/python-list__;!!Cn_UX_p3!mrESxAj9YCHsdtNAfkNiY-Zf6U3WTIqaNrgBmbw1ELlQy51ilob43dD0ONsqvg4a94MEdOdwomgyqfyABbvRnA$
>

--
https://urldefense.com/v3/__https://mail.python.org/mailman/listinfo/python-list__;!!Cn_UX_p3!mrESxAj9YCHsdtNAfkNiY-Zf6U3WTIqaNrgBmbw1ELlQy51ilob43dD0ONsqvg4a94MEdOdwomgyqfyABbvRnA$
-- 
https://mail.python.org/mailman/listinfo/python-list

Re: Ref-strings in logging messages (was: Performance issue with CPython 3.10 + Cython)

[Barry]

> On 7 Oct 2022, at 18:16, MRAB  wrote:
> 
> On 2022-10-07 16:45, Skip Montanaro wrote:
>>> On Fri, Oct 7, 2022 at 9:42 AM Andreas Ames 
>>> wrote:
>>> 1. The culprit was me. As lazy as I am, I have used f-strings all over the
>>> place in calls to `logging.logger.debug()` and friends, evaluating all
>>> arguments regardless of whether the logger was enabled or not.
>>> 
>> I thought there was some discussion about whether and how to efficiently
>> admit f-strings to the logging package. I'm guessing that's not gone
>> anywhere (yet).
> Letting you pass in a callable to call might help because that you could use 
> lambda.

Yep, that’s the obvious way to avoid expensive log data generation.
Would need logging module to support that use case.

Barry

> -- 
> https://mail.python.org/mailman/listinfo/python-list
> 

-- 
https://mail.python.org/mailman/listinfo/python-list

Re: Ref-strings in logging messages (was: Performance issue with CPython 3.10 + Cython)

[MRAB]

On 2022-10-07 16:45, Skip Montanaro wrote:

On Fri, Oct 7, 2022 at 9:42 AM Andreas Ames 
wrote:


1. The culprit was me. As lazy as I am, I have used f-strings all over the
place in calls to `logging.logger.debug()` and friends, evaluating all
arguments regardless of whether the logger was enabled or not.



I thought there was some discussion about whether and how to efficiently
admit f-strings to the logging package. I'm guessing that's not gone
anywhere (yet).

Letting you pass in a callable to call might help because that you could 
use lambda.

--
https://mail.python.org/mailman/listinfo/python-list

Re: Ref-strings in logging messages (was: Performance issue with CPython 3.10 + Cython)

[Barry]

> On 7 Oct 2022, at 16:48, Skip Montanaro  wrote:
> 
> On Fri, Oct 7, 2022 at 9:42 AM Andreas Ames 
> wrote:
> 
>> 1. The culprit was me. As lazy as I am, I have used f-strings all over the
>> place in calls to `logging.logger.debug()` and friends, evaluating all
>> arguments regardless of whether the logger was enabled or not.
>> 
> 
> I thought there was some discussion about whether and how to efficiently
> admit f-strings to the logging package. I'm guessing that's not gone
> anywhere (yet).

That cannot be done as the f-string is computed before the log call.

Maybe you are thinking of the lazy expression idea for this. That idea
seems to have got no where as its not clear how to implement it without
performance issues.

Barry

> 
> Skip
> -- 
> https://mail.python.org/mailman/listinfo/python-list
> 

-- 
https://mail.python.org/mailman/listinfo/python-list

Re: Ref-strings in logging messages (was: Performance issue with CPython 3.10 + Cython)

[Skip Montanaro]

Dang autocorrect. Subject first word was supposed to be "f-strings" not
"ref-strings." Sorry about that.

S

On Fri, Oct 7, 2022, 10:45 AM Skip Montanaro 
wrote:

>
>
> On Fri, Oct 7, 2022 at 9:42 AM Andreas Ames 
> wrote:
>
>> 1. The culprit was me. As lazy as I am, I have used f-strings all over the
>> place in calls to `logging.logger.debug()` and friends, evaluating all
>> arguments regardless of whether the logger was enabled or not.
>>
>
> I thought there was some discussion about whether and how to efficiently
> admit f-strings to the logging package. I'm guessing that's not gone
> anywhere (yet).
>
> Skip
>
-- 
https://mail.python.org/mailman/listinfo/python-list

Ref-strings in logging messages (was: Performance issue with CPython 3.10 + Cython)

[Skip Montanaro]

On Fri, Oct 7, 2022 at 9:42 AM Andreas Ames 
wrote:

> 1. The culprit was me. As lazy as I am, I have used f-strings all over the
> place in calls to `logging.logger.debug()` and friends, evaluating all
> arguments regardless of whether the logger was enabled or not.
>

I thought there was some discussion about whether and how to efficiently
admit f-strings to the logging package. I'm guessing that's not gone
anywhere (yet).

Skip
-- 
https://mail.python.org/mailman/listinfo/python-list