Add detailed trace mode showing saved object size and visual depth level #471

leogama · 2022-05-08T17:21:03Z

This is a detailed mode for the trace feature to help to better visualize the hierarchy of the objects being dumped and also to identify large child objects. If it is OK, I will write the documentation.

Usage:

import dill
dill.detect.trace(True, detail=True)
pickled = dill.dumps(obj)

anivegesana · 2022-05-08T18:28:45Z

dill/_dill.py

@@ -1176,7 +1211,7 @@ def _save_with_postproc(pickler, reduction, is_pickler_dill=None, obj=Getattr.NO
 # License: https://github.com/cloudpipe/cloudpickle/blob/master/LICENSE
 @register(CodeType)
 def save_code(pickler, obj):
-    log.info("Co: %s" % obj)
+    pickler._log_trace("Co: %s", obj)


Because of limitations from long ago (#456), the pickler that is passed into the registered save functions is not necessarily a dill pickler and could have a missing _log_trace function.

I think that formatting the log trace as a tree is a good idea, but I think you should be using a Formatter instead of the pickler itself to do this:

https://stackoverflow.com/questions/35048921/format-log-messages-as-a-tree

Oh, now I get the whole is_dill() thing. It is related to other packages that also extend pickle. I'll take a look at Formatter then.

Other people can use the default pickler pickle.Pickler instead of dill.Pickler and they shouldn't see an error. This system is like this because in older versions of Python, the pickler class couldn't have its own dispatch. I think that it would be quick change to make the dispatch per class instead of global (cloudpickle did it), but it may be a breaking change and I didn't find time to verify that it isn't.

I think it's not so hard to verify whether the package is working after such a change, but for code that extends dill it could be tricky. There are both benefits and drawbacks of being able to extend pickle just by importing dill. Maybe it could be made an optional feature somehow.

Hey, look at this! My notes from learning how to use logging.Formatter (it's a lot of fun):

Basic calling sequence with StreamHandler and Formatter in Python 3.7: (All methods from the second line on are from logging.__init__.py) dill.logging.logger.log -> (or info, warning, etc.) Logger.log -> Logger._log -> Logger.makeRecord -> LogRecord.__init__ Logger.handle -> Logger.callHandlers -> Handler.handle -> StreamHandler.emit -> Handler.format -> Formatter.format -> LogRecord.getMessage Formatter.formatMessage -> PercentStyle.format

mmckerns · 2022-05-09T12:11:10Z

So dill has a script that uses objgraph to get a visual understanding of some of the same information that trace provides. Just FYI in case you aren't aware of it...

leogama · 2022-05-09T12:34:47Z

So dill has a script that uses objgraph to get a visual understanding of some of the same information that trace provides. Just FYI in case you aren't aware of it...

I did saw it. It's a good tool to get an overview of large objects or entire module structures. My proposed addition is meant for detailed inspection of a single or few objects in the pickle, and the "tree style" is just a visual hint to help you to find it in the middle of a long log. An option for objgraph to visualize object sizes would be interesting, though.

leogama · 2022-05-09T15:02:41Z

Refactored the code using logging classes. Seems good.

mmckerns · 2022-05-09T16:22:27Z

I think that formatting the log trace as a tree is a good idea

I agree.

…level

leogama · 2022-05-09T19:33:13Z

For me it's done. Feel free to edit the trace tree style in the formatter if you like.

leogama · 2022-05-09T19:35:39Z

Here is a sample output from the test_dictviews.py file:

> Dk: <dict_keys(['a'])>
>> Wr: <method 'keys' of 'dict' objects>
>>> F2: <function _getattr at 0x7fd372962820>
>>> # F2 (26 B)
>>> T1: <class 'dict'>
>>>> F2: <function _load_type at 0x7fd37295db80>
>>>> # F2 (17 B)
>>> # T1 (28 B)
>> # Wr (101 B)
> # Dk (156 B)
> Dv: <dict_values([1])>
>> Wr: <method 'values' of 'dict' objects>
>>> F2: <function _getattr at 0x7fd372962820>
>>> # F2 (26 B)
>>> T1: <class 'dict'>
>>>> F2: <function _load_type at 0x7fd37295db80>
>>>> # F2 (17 B)
>>> # T1 (28 B)
>> # Wr (105 B)
>> T1: <class 'enumerate'>
>> # T1 (18 B)
> # Dv (168 B)
> Di: <dict_items([('a', 1)])>
>> Wr: <method 'items' of 'dict' objects>
>>> F2: <function _getattr at 0x7fd372962820>
>>> # F2 (26 B)
>>> T1: <class 'dict'>
>>>> F2: <function _load_type at 0x7fd37295db80>
>>>> # F2 (17 B)
>>> # T1 (28 B)
>> # Wr (103 B)
>> D2: <dict object at 0x7fd37296ef00>
>> # D2 (9 B)
> # Di (116 B)

anivegesana · 2022-05-09T22:55:37Z

Personally, I am more of a fan of blank space indentation or box drawing characters. If you think that is a good idea, I can look into later to see if it will look nicer that way without adding overhead.

https://en.m.wikipedia.org/wiki/Box_Drawing

anivegesana · 2022-05-10T02:54:29Z

@leogama Thoughts? leogama#1

┬ Dkvi: <dict_keys(['a'])>
├┬ Wr: <method 'keys' of 'dict' objects>
│├┬ F2: <function _getattr at 0x10af83b50>
││└ # F2 (26 B)
│├┬ T1: <class 'dict'>
││├┬ F2: <function _load_type at 0x10af82ef0>
│││└ # F2 (17 B)
││└ # T1 (28 B)
│└ # Wr (101 B)
├┬ D2: <dict object at 0x10ac88880>
│└ # D2 (9 B)
└ # Dkvi (114 B)

leogama · 2022-05-10T05:09:53Z

Sleek! I will just add a fallback clause for non-UTF-8 terminals just in case.

anivegesana · 2022-05-10T15:56:28Z

Ah yes. Keep forgetting that Python 2 is still supported by dill. Glad you like it!

leogama · 2022-05-11T11:07:34Z

Ah yes. Keep forgetting that Python 2 is still supported by dill.

Actually, I had to work really hard to get ASCII output, which I eventually did with env -i LC_ALL=C python2. It seems that Python 2 also uses UTF-8 encoding for terminal output in most cases. But there must be some really dumb terminals out there.

And the Unicode strings were necessary just for the translate() method to work with Unicode characters. Otherwise it was working just fine.

@mmckerns Any final thoughts?

dill/logger.py

mmckerns

Please address the comments. Otherwise, LGTM.

dill/logger.py

mmckerns

Let's make the suggested change to improve code compatibility across this PR.

dill/_dill.py

leogama · 2022-06-24T14:01:03Z

@mmckerns and @anivegesana: what do you think of converting trace to a context manager?

class trace:
    """print a trace through the stack when pickling; useful for debugging"""
    def __init__(self, boolean=None):
        self.boolean = boolean
        if boolean is not None:
            logger.setLevel(logging.INFO if boolean else logging.WARNING)
    def __enter__(self):
        self.previous_level = logger.level
        logger.setLevel(logging.INFO)
        return logger
    def __exit__(self, *exc_info):
        logger.setLevel(self.previous_level)
        return False
    def __repr__(self):
        if self.boolean is None:
            return super().__repr__()
        return "dill trace is %s" % ("ON" if self.boolean else "OFF")

It can be used in the same way as before too, but using it as a context manager preserves the previous log level:

>>> from dill import detect, dumps
>>> from dill.logger import logger
>>> d = {'a': 1, 'b': {}}
>>> logger.setLevel(40)
>>> detect.trace(True)
dill trace is ON
>>> _ = dumps(d)
┬ D2: <dict object at 0x7f83c2176180>
├┬ D2: <dict object at 0x7f83c2188c40>
│└ # D2 [2 B]
└ # D2 [16 B]
>>> detect.trace(False)
dill trace is OFF
>>> _ = dumps(d)  # no trace
>>> logger.level
30
>>> logger.setLevel(40)
>>> with detect.trace():
>>>     dumps(d)
┬ D2: <dict object at 0x7f83c2176180>
├┬ D2: <dict object at 0x7f83c2188c40>
│└ # D2 [2 B]
└ # D2 [16 B]
>>> _ = dumps(d)  # no trace
>>> logger.level
40

mmckerns

LGTM. Will you be adding the context manager to this PR? I'll approve or defer depending on your response.

leogama · 2022-06-25T18:31:39Z

LGTM. Will you be adding the context manager to this PR? I'll approve or defer depending on your response.

Yes, I prefer to finish this in one shot. Let me just update the documentation and add a test and we can close it.

leogama · 2022-06-25T22:22:25Z

I've made the context manager implementation separated lately.

dill/logger.py

mmckerns

Please address the two comments on the context manager. Otherwise, LGTM.

anivegesana reviewed May 8, 2022

View reviewed changes

leogama force-pushed the log-trace branch from fef0370 to a68286c Compare May 9, 2022 15:01

leogama added 2 commits May 9, 2022 15:40

Add detailed trace mode showing dumped object size and visual depeth …

9c3c589

…level

Tests: logging code coverage

1885df1

leogama force-pushed the log-trace branch from a68286c to 1885df1 Compare May 9, 2022 18:42

logger: just show size after writing object

5452dd7

leogama force-pushed the log-trace branch from 7c4ee7c to 5452dd7 Compare May 9, 2022 19:29

anivegesana and others added 2 commits May 10, 2022 02:12

Box drawing formatting

df05fc2

fallback for non-UTF-8 terminals

c141398

mmckerns added this to the dill-0.3.6 milestone May 29, 2022

mmckerns self-requested a review June 5, 2022 09:47

mmckerns added the enhancement label Jun 7, 2022

mmckerns reviewed Jun 7, 2022

View reviewed changes

dill/logger.py Outdated Show resolved Hide resolved

mmckerns requested changes Jun 7, 2022

View reviewed changes

dill/logger.py Outdated Show resolved Hide resolved

leogama added 2 commits June 22, 2022 11:30

review: corrections and improvements

e757769

Merge branch 'master' into log-trace

c34c588

leogama requested a review from mmckerns June 22, 2022 14:42

mmckerns requested changes Jun 22, 2022

View reviewed changes

dill/_dill.py Outdated Show resolved Hide resolved

review: adjustments

4ed8479

leogama requested a review from mmckerns June 24, 2022 02:06

leogama added 3 commits June 23, 2022 23:14

split module imports into separated lines

70b67f6

deal with non-standardized UTF-8 encoding name

ebd3f54

update sample trace in module docs

cf25de0

mmckerns reviewed Jun 24, 2022

View reviewed changes

use trace() as a context manager

ffa59d7

leogama requested a review from mmckerns June 25, 2022 21:49

pypy special cases

d3b05b5

mmckerns reviewed Jun 26, 2022

View reviewed changes

dill/logger.py Outdated Show resolved Hide resolved

mmckerns requested changes Jun 26, 2022

View reviewed changes

accept file handle in trace context manager

a5b9a39

leogama requested a review from mmckerns June 26, 2022 19:48

fix dict (PyPy) and mappingproxy (CPython) trace

60c154c

mmckerns approved these changes Jul 1, 2022

View reviewed changes

mmckerns merged commit 9000ab9 into uqfoundation:master Jul 1, 2022

leogama deleted the log-trace branch July 1, 2022 21:07

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add detailed trace mode showing saved object size and visual depth level #471

Add detailed trace mode showing saved object size and visual depth level #471

leogama commented May 8, 2022 •

edited

Loading

anivegesana May 8, 2022

leogama May 8, 2022

anivegesana May 8, 2022

leogama May 8, 2022

mmckerns commented May 9, 2022

leogama commented May 9, 2022

leogama commented May 9, 2022

mmckerns commented May 9, 2022

leogama commented May 9, 2022 •

edited

Loading

leogama commented May 9, 2022

anivegesana commented May 9, 2022

anivegesana commented May 10, 2022 •

edited

Loading

leogama commented May 10, 2022

anivegesana commented May 10, 2022

leogama commented May 11, 2022

mmckerns left a comment

mmckerns left a comment

leogama commented Jun 24, 2022 •

edited

Loading

mmckerns left a comment

leogama commented Jun 25, 2022

leogama commented Jun 25, 2022

mmckerns left a comment •

edited

Loading

Add detailed trace mode showing saved object size and visual depth level #471

Add detailed trace mode showing saved object size and visual depth level #471

Conversation

leogama commented May 8, 2022 • edited Loading

anivegesana May 8, 2022

Choose a reason for hiding this comment

leogama May 8, 2022

Choose a reason for hiding this comment

anivegesana May 8, 2022

Choose a reason for hiding this comment

leogama May 8, 2022

Choose a reason for hiding this comment

mmckerns commented May 9, 2022

leogama commented May 9, 2022

leogama commented May 9, 2022

mmckerns commented May 9, 2022

leogama commented May 9, 2022 • edited Loading

leogama commented May 9, 2022

anivegesana commented May 9, 2022

anivegesana commented May 10, 2022 • edited Loading

leogama commented May 10, 2022

anivegesana commented May 10, 2022

leogama commented May 11, 2022

mmckerns left a comment

Choose a reason for hiding this comment

mmckerns left a comment

Choose a reason for hiding this comment

leogama commented Jun 24, 2022 • edited Loading

mmckerns left a comment

Choose a reason for hiding this comment

leogama commented Jun 25, 2022

leogama commented Jun 25, 2022

mmckerns left a comment • edited Loading

Choose a reason for hiding this comment

leogama commented May 8, 2022 •

edited

Loading

leogama commented May 9, 2022 •

edited

Loading

anivegesana commented May 10, 2022 •

edited

Loading

leogama commented Jun 24, 2022 •

edited

Loading

mmckerns left a comment •

edited

Loading