Add cache miss logging #165

sbrunner · 2019-10-18T14:22:58Z

It's relay useful to know which keys is regenerated.

4383

Hello,

Thanks for these changes, see my comments inline.

4383 · 2019-10-18T14:27:37Z

dogpile/cache/region.py

@@ -879,6 +882,7 @@ def get_value():
                    value.metadata["ct"]
                )
            ):
+                log.info('Cache miss for key: %s', orig_key)


Can you reword this with something like Missing cache for key: %s

4383 · 2019-10-18T14:27:43Z

dogpile/cache/region.py

@@ -32,6 +33,8 @@

 """

+log = logging.getLogger('c2cwsgiutils.' + __name__)


Any reason to use c2cwsgiutils here?
The module name is not enough?

Oups, missing to remove ...

hehe no problems :)

sbrunner · 2019-10-18T14:32:20Z

Thanks @4383 , done :-)

sqla-tester

OK, this is sqla-tester setting up my work to try to get revision 0b7a5fb of this pull request into gerrit so we can run tests and reviews and stuff

sqla-tester · 2019-10-18T14:34:39Z

New Gerrit review created for change 0b7a5fb: https://gerrit.sqlalchemy.org/#/c/sqlalchemy/dogpile.cache/+/1528

sqla-tester

Hervé Beraud (4383) wrote:

Code-Review-1

(1 comment)

Some comment related to your commit message:

/COMMIT_MSG (line 9): I think we can reword the commit message with something like:

Log missing cache keys

When a cache is missing then we log the key to provide some useful informations to users.

zzzeek

hi there -

There was no issue opened for this so this is the first chance we have to talk about the subject area here of "region should include logging". It should! great idea. But I like to create a full feature rather than adding one liners, that is, think about what people would usually want in this area, not just one thing that we thought of. Please review a few comments I have as far as if we do have logging in region, things we would reasonably expect someone to see in those logs. also I hope that you can review the existing logging that's in lock.

as far as tests, I can relax that there are not tests for these logging statements for now as there are also no tests for the logging in lock.py.

dogpile/cache/region.py

sqla-tester · 2019-10-18T15:20:55Z

mike bayer (zzzeek) wrote:

(1 comment)

sbrunner · 2019-10-18T15:26:56Z

@zzzeek I see your comments, I will work on them the next week :-)

sbrunner · 2019-10-21T11:15:55Z

@zzzeek For me do the changes for all your comment, is it OK for you, are the message good or should be improved?
Thanks in advance :-)

zzzeek · 2019-10-21T15:03:11Z

@zzzeek For me do the changes for all your comment, is it OK for you, are the message good or should be improved?
Thanks in advance :-)

I might refactor some of the verbosity here but can you make the %s into %r for the orig_key , I think it's safer

zzzeek · 2019-10-21T15:08:32Z

like a function that can be reused in both


def _is_cache_miss(self, value, orig_key):
    if value is NO_VALUE:
        log.debug('Generate cache for key: %r', orig_key)
    elif value.metadata["v"] != value_version:
        log.debug('Update cache for key: %r', orig_key)
    elif self.region_invalidator.is_hard_invalidated(
            value.metadata["ct"]
    ):
        log.debug('Update hard invalidated cache for key: %r', orig_key)
    else:
        return True

    return False


if self._is_cache_miss(value, orig_key):
    raise NeedRegenerationException()

sbrunner · 2019-10-22T07:16:50Z

@zzzeek Good improvement thanks => fixed :-)

sqla-tester

OK, this is sqla-tester setting up my work to try to get revision b46bb31 of this pull request into gerrit so we can run tests and reviews and stuff

sqla-tester · 2019-10-22T22:29:24Z

Patchset b46bb31 added to existing Gerrit review https://gerrit.sqlalchemy.org/#/c/sqlalchemy/dogpile.cache/+/1528

sqla-tester

OK, this is sqla-tester setting up my work to try to get revision 693b6b0 of this pull request into gerrit so we can run tests and reviews and stuff

sqla-tester · 2019-10-24T07:20:51Z

Patchset 693b6b0 added to existing Gerrit review https://gerrit.sqlalchemy.org/#/c/sqlalchemy/dogpile.cache/+/1528

When a cache is missing then we log the key to provide some useful informations to users.

sqla-tester

OK, this is sqla-tester setting up my work to try to get revision 9e519cf of this pull request into gerrit so we can run tests and reviews and stuff

sqla-tester · 2019-10-24T09:23:20Z

Patchset 9e519cf added to existing Gerrit review https://gerrit.sqlalchemy.org/#/c/sqlalchemy/dogpile.cache/+/1528

sbrunner · 2019-10-24T11:04:27Z

For me it's ready to be merge, thanks in advance :-)

sqla-tester

Hervé Beraud (4383) wrote:

(1 comment)

Hello,

Some comments inline:

sqla-tester · 2019-10-24T12:41:09Z

dogpile/cache/region.py

                new_values = creator(*keys_to_get)
+                log.debug(
+                    'Generate cache in %.2f s. for key: %r',


Hervé Beraud (4383) wrote:

IMHO, I think it's most useful to print here the cache creation date and time instead of the used time to generate the cache.

This operation will surely only take just few miliseconds to generate this cache... In other words this information isn't reallly useful.

Also, I'm not sure, I do not have related benchmark, but I guess %.2f isn't enough to represent a quick treatment like this, possibly you will to only display "0.00 s" the most of the time.

As a user of this module I prefer know when my cache was created rather than the time used to generate it.

Thoughts?

this could be a slow query against a database or web service and can take any arbitrary amount of time, it could be minutes or any amount of time, which is useful to see in the logs as it would describe why a request is hanging. or if the async runner is used it can take minutes or hours while the app continues to run normally. dogpile.cache's use case is for optimizing data fetches that may be slow, it's the most important number to see in the logs really.

also the log line will have the timestamp, so that's the time in which the finished value was created

Good point :)

sqla-tester

OK, this is sqla-tester setting up my work to try to get revision 9e519cf of this pull request into gerrit so we can run tests and reviews and stuff

sqla-tester · 2019-10-24T14:21:15Z

Patchset 9e519cf added to existing Gerrit review https://gerrit.sqlalchemy.org/#/c/sqlalchemy/dogpile.cache/+/1528

sqla-tester

mike bayer (zzzeek) wrote:

(1 comment)

sqla-tester · 2019-10-24T14:39:22Z

dogpile/cache/region.py

+                log.debug(
+                    'Generate cache in %.2f s. for key: %r',
+                    time.time() - start_time, orig_key
+                )


mike bayer (zzzeek) wrote:

creator is against keys_to_get here. I'll get this fixed up, thanks!

sqla-tester · 2019-10-24T18:06:13Z

mike bayer (zzzeek) wrote:

Okey doke, if one or both people reviewing this could come over to the gerrit, e.g. https://gerrit.sqlalchemy.org/#/c/sqlalchemy/dogpile.cache/+/1528/ , and look over the whole thing and try to find anything wrong, typos, something that won't work, etc., that would be great. I've run some demo scripts to see what the logging looks like and there's also some unit tests.

sqla-tester · 2019-10-25T08:34:51Z

Hervé Beraud (4383) wrote:

Code-Review+1

LGTM

sqla-tester · 2019-10-25T22:27:58Z

mike bayer (zzzeek) wrote:

Code-Review+2 Workflow+1

sqla-tester · 2019-10-25T22:27:59Z

Gerrit review https://gerrit.sqlalchemy.org/1528 has been merged. Congratulations! :)

sbrunner · 2019-10-28T12:21:37Z

Thanks :-)

When do you plane to have a new release?
If not quickly, is it possible to have a dev release?

CU and Thanks in advance :-)

zzzeek · 2019-10-28T16:36:48Z

it's released and note I am slowly starting to use semver on SQLAlchemy projects other than SQLAlchemy itself.

sbrunner · 2019-10-28T16:55:39Z

Excellent, thanks :-)

4383 reviewed Oct 18, 2019

View reviewed changes

4383 requested a review from sqla-tester October 18, 2019 14:34

sqla-tester reviewed Oct 18, 2019

View reviewed changes

zzzeek requested changes Oct 18, 2019

View reviewed changes

dogpile/cache/region.py Outdated Show resolved Hide resolved

dogpile/cache/region.py Outdated Show resolved Hide resolved

dogpile/cache/region.py Outdated Show resolved Hide resolved

dogpile/cache/region.py Outdated Show resolved Hide resolved

sbrunner mentioned this pull request Oct 21, 2019

Configure the dogpile cache log level camptocamp/c2cgeoportal#5419

Merged

zzzeek requested a review from sqla-tester October 22, 2019 22:29

sqla-tester reviewed Oct 22, 2019

View reviewed changes

sbrunner requested a review from sqla-tester October 24, 2019 07:20

sqla-tester reviewed Oct 24, 2019

View reviewed changes

Log missing cache keys, with reason ind time

9e519cf

When a cache is missing then we log the key to provide some useful informations to users.

sbrunner requested a review from sqla-tester October 24, 2019 09:23

sqla-tester reviewed Oct 24, 2019

View reviewed changes

zzzeek requested a review from sqla-tester October 24, 2019 14:21

sqla-tester reviewed Oct 24, 2019

View reviewed changes

sqlalchemy-bot closed this in 33e5dcd Oct 25, 2019

sbrunner deleted the add-cache-miss-logging branch October 28, 2019 16:33

		@@ -32,6 +33,8 @@

		"""

		log = logging.getLogger('c2cwsgiutils.' + __name__)

Add cache miss logging #165

Add cache miss logging #165

Conversation

sbrunner commented Oct 18, 2019

4383 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

4383 Oct 18, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

4383 Oct 18, 2019 • edited Loading

Choose a reason for hiding this comment

sbrunner commented Oct 18, 2019

sqla-tester left a comment

Choose a reason for hiding this comment

sqla-tester commented Oct 18, 2019

sqla-tester left a comment

Choose a reason for hiding this comment

zzzeek left a comment

Choose a reason for hiding this comment

sqla-tester commented Oct 18, 2019

sbrunner commented Oct 18, 2019

sbrunner commented Oct 21, 2019

zzzeek commented Oct 21, 2019

zzzeek commented Oct 21, 2019

sbrunner commented Oct 22, 2019

sqla-tester left a comment

Choose a reason for hiding this comment

sqla-tester commented Oct 22, 2019

sqla-tester left a comment

Choose a reason for hiding this comment

sqla-tester commented Oct 24, 2019

sqla-tester left a comment

Choose a reason for hiding this comment

sqla-tester commented Oct 24, 2019

sbrunner commented Oct 24, 2019

sqla-tester left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sqla-tester left a comment

Choose a reason for hiding this comment

sqla-tester commented Oct 24, 2019

sqla-tester left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sqla-tester commented Oct 24, 2019

sqla-tester commented Oct 25, 2019

sqla-tester commented Oct 25, 2019

sqla-tester commented Oct 25, 2019

sbrunner commented Oct 28, 2019

zzzeek commented Oct 28, 2019

sbrunner commented Oct 28, 2019

4383 Oct 18, 2019 •

edited

Loading

4383 Oct 18, 2019 •

edited

Loading