Key Error: mode when running either austin2speedscope or austin2pprof on windows 10

[skewballfox]

Description

upon running either austin2speedcope.exe input.austin output.speedscope or austin2pprof.exe input.austin output.pprof I run into the following error:

  File "<pythonpath>\LocalCache\local-packages\Python310\site-packages\austin\format\speedscope.py", line 212, in main
    mode = fin.metadata["mode"]
KeyError: 'mode'

Steps to Reproduce

1. generate a austin profile via austin -P .\.venv\Scripts\python.exe launch.py 1>wall_time.austin
2. run either command to convert the file to another format

Expected behavior: [What you expect to happen]

conversion happens and new file is created
Actual behavior: [What actually happens]
command errors out with a stacktrace ending in the above message

Reproduces how often: [What percentage of the time does it reproduce?]
100%

Versions

PS > austin --version
austin 3.5.0
PS > austin2pprof.exe --version
0.1.0
PS > austin-compress.exe --version
0.2.0
PS > austin2speedscope.exe --version
0.2.1
PS > python --version
Python 3.10.10

this is on windows 10

Additional Information

this seems related to the Metadata class inside stats.py.
mode is one of the metadata fields listed at the top of the austin output file (in the output from the command in the steps to reproduce the line reads # mode: wall

[P403n1x87]

@skewballfox thanks for reporting this. Can I double-check with you that by

mode is one of the metadata fields listed at the top of the austin output file

you mean that the data you have collected from austin contains the # mode: wall line, please? I have tried to reproduce this on a mac but the austin2... commands seem to work as expected. I'll give it a go on a Windows machine as well soon to confirm.

[P403n1x87]

I've tested with austin -P python -c "from time import sleep; sleep(2)" within a virtual environment and I was able to convert the data to the speedscope format. I look forward to your confirmation that indeed # mode: wall is contained in your sample file.

[skewballfox]

[Here's the line responsible for it in Austin]( https://github.com/P403n1x87/austin/blob/b48d980f6f3d0808d9221ee611a9c3094e02bb50/src/logging.c#L201 )

…

On Sun, Mar 19, 2023, 5:08 PM Gabriele N. Tornetta ***@***.***> wrote: I've tested with austin -P python -c "from time import sleep; sleep(2)" within a virtual environment and I was able to convert the data to the speedscope format. I look forward to your confirmation that indeed # mode: wall is contained in your sample file. — Reply to this email directly, view it on GitHub <#16 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AG7UDR7RQBBDACDMJIKEQ5DW457WXANCNFSM6AAAAAAV67LHLM> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[skewballfox]

hey, sorry for the delay. This is the metadata from the file in question

# austin: 3.5.0
# interval: 100
# mode: wall
# python: 3.10.10

[P403n1x87]

@skewballfox thanks for confirming that indeed all the metadata is available from the sample file. If the file in question does not contain any sensitive data, would you perhaps be able to share it so that I can do some local testing on it?

[skewballfox]

I wish I could but while the project doesn't contain any sensitive information, it's export controlled. plus, it's pretty gargantuan about a Gigabyte in size.

[emeryberger]

Not sure if this is related: austin2pprof does not seem to be generating legal pprof output on either Mac or Linux -- at least Perfetto.dev can't read the generated pprof file.

Trivial small example program, original Austin output, and austin2pprof generated pprof file attached. Screenshot of failure from perfetto.dev below.

Command line: sudo austin -i 500ms -o testme-austin.out python3 testme.py

testme.zip

Note: speedscope output via austin2speedscope works fine.

[P403n1x87]

@emeryberger thanks for reporting this. I have opened the attached pprof file with pprof and (besides the expected complaint about the missing binary) the data seems to load fine

Getting a raw view of the protobuf data shows the full structure

$ go tool pprof -raw testme-austin.pprof
Main binary filename not available.
PeriodType:
Period: 0
Samples:
Wall time/μs
    2519787: 1 2
                Process ID:[92879] Thread ID:[0:7908102144]
     500431: 3 2
                Process ID:[92879] Thread ID:[0:7908102144]
Locations
     1: 0x0 M=1 increment /Users/emerydb/Documents/testme.py:7 s=0()
     2: 0x0 M=1 <module> /Users/emerydb/Documents/testme.py:9 s=0()
     3: 0x0 M=1 increment /Users/emerydb/Documents/testme.py:6 s=0()
Mappings
1: 0x0/0x0/0x0

I suspect that the Perfetto UI is perhaps expecting a somewhat different structure, considering that it seems to be mainly a tool for traces (the error also hints at ftrace: ftrace_bundle_tokenizer_errors). This is all I have been able to find out about file formats https://perfetto.dev/docs/quickstart/traceconv. So my guess would be that a pprof is not necessarily compatible with the Perfetto UI.

[yuzaoyah]

Hi, @P403n1x87 . I met similar problem, "Key Error: mode" when using austin2speedscope.

D:\>austin2speedscope profile_10min.austin profile_10min.json
Traceback (most recent call last):
  File "D:\py310\lib\site-packages\austin\format\speedscope.py", line 227, in main
    mode = fin.metadata["mode"]
KeyError: 'mode'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "D:\py310\lib\runpy.py", line 196, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "D:\py310\lib\runpy.py", line 86, in _run_code
    exec(code, run_globals)
  File "D:\py310\Scripts\austin2speedscope.exe\__main__.py", line 7, in <module>
  File "D:\py310\lib\site-packages\austin\format\speedscope.py", line 226, in main
    with AustinFileReader(args.input) as fin:
  File "D:\py310\lib\site-packages\austin\format\collapsed_stack.py", line 144, in __exit__
    self.stream.flush()
AttributeError: 'str' object has no attribute 'flush'

My env:
windwos 11
python 3.10.10
austin 3.7.0 [gcc 12.2.0]
austin-python 2.1.0

My cmd:

austin.exe -C -f -i 100 -x 6 -p 21012 -o profile_10min.austin
austin2speedscope profile_10min.austin profile_10min.json  # error

and some lines in profile_10min.austin like this:

#  austin: 3.7.0
# interval: 100
# mode: full
# memory: 16777216
# multiprocess: on

P16272;T0:572c;D:\py310\lib\runpy.py:_run_module_as_main:196;D:\py310\lib\runpy.py:_run_code:86;E:\media_pull\src\consumer\execution_google_consumer.py:<module>:167;D:\py310\lib\asyncio\runners.py:run:44;D:\py310\lib\asyncio\base_events.py:run_until_complete:636;D:\py310\lib\asyncio\windows_events.py:run_forever:321;D:\py310\lib\asyncio\base_events.py:run_forever:603;D:\py310\lib\asyncio\base_events.py:_run_once:1871;D:\py310\lib\asyncio\events.py:_run:95 279,1,95064064
P16272;T0:5a04;D:\py310\lib\threading.py:_bootstrap:973;D:\py310\lib\threading.py:_bootstrap_inner:1016;D:\py310\lib\threading.py:run:953;D:\py310\lib\concurrent\futures\thread.py:_worker:81 4208,1,0

I see some codes, and i think that maybe this is reason.

austin\format\speedscope.py

    try:
        with AustinFileReader(args.input) as fin:
            mode = fin.metadata["mode"]
            speedscope = Speedscope(os.path.basename(args.input), mode, args.indent)
            for event in fin:
                if not isinstance(event, AustinSample):
                    continue
                try:
                    speedscope.add_sample(event)
                except InvalidSample:
                    continue

    except FileNotFoundError:
        print(f"No such input file: {args.input}")
        exit(1)

The error happend in "mode = fin.metadata["mode"]". Wanting to get key "mode" but "AustinFileReader(args.input)" has not calling "__iter__" which read the "args.input" and writes data to dict metadata including "mode" as following. So the error happend.

class AustinFileReader(AustinEventIterator):
    """Austin file reader.

    Conveniently read an Austin sample file by also parsing any header and
    footer metadata.
    """

    def __init__(self, stream: t.TextIO) -> None:
        self.metadata: t.Dict[str, str] = {}
        self.stream: t.TextIO = stream

    def __enter__(self) -> "AustinFileReader":
        """Open the Austin file and read the metadata."""
        return self

    def __iter__(self) -> t.Iterator[AustinEvent]:
        """Iterator over the samples in the Austin file."""
        for line in self.stream:
            if not line:
                break
            line = line.rstrip("\n")
            if not line:
                continue
            if line.startswith("# "):
                key, _, value = line[2:].strip().partition(": ")
                self.metadata[key] = value
                yield AustinMetadata(name=key, value=value)
            else:
                yield parse_collapsed_stack(line)

    def __exit__(self, *args: t.Any) -> None:
        """Close the Austin file."""
        self.stream.flush()

I try fixing this, and success to generate speedscope json file:

    try:
        with AustinFileReader(open(args.input, mode="r")) as fin:
            speedscope = None
            for event in fin:
                if not isinstance(event, AustinSample):
                    continue
                if not speedscope:
                    speedscope = Speedscope(os.path.basename(args.input), fin.metadata["mode"], args.indent)
                try:
                    speedscope.add_sample(event)
                except InvalidSample:
                    continue

    except FileNotFoundError:
        print(f"No such input file: {args.input}")
        exit(1)

[P403n1x87]

@yuzaoyah thanks for your report. This is likely a regression in version 2 of austin-python, which is supposed to target the upcoming Austin 4 release. I believe the problem goes away if you downgrade to the latest v1 release of austin-python for now.