Unexpected stop in dump data from coreprofilesessiontap

[Nnnnut]

Test environment

• macOS 14.1.1
• iPhone15 pro max, iOS 17.1.1

Describe the bug I run this command: python -m pymobiledevice3 developer dvt core-profile-session save core.trace --rsd xxx xxx

It continuously dump data after running, But it can only last for a few minutes or even tens of seconds. Is that running normally? In my expectation, it should continue to run until I manually stop it.

To Reproduce

1. Modified the following code to add logs in pymobiledevice3/services/dvt/instruments/core_profile_session_tap.py:

   import logging
   logger = logging.getLogger('Tap')
   
   ...
   
   def dump(self, out: typing.BinaryIO, timeout: int = None):
           """
           Dump data from core profile session to a file.
           :param out: File object to write data to.
           :param timeout: Timeout for data dumping, in seconds.
           """
           start = time.time()
           while timeout is None or time.time() <= start + timeout:
               logger.info(f'receive_message start')       # ---- added code
               data = self.channel.receive_message()
               logger.info(f'receive_message end')         # ---- added code
               if data.startswith(STACKSHOT_HEADER) or data.startswith(b'bplist'):
                   logger.info(f'Receiving trace data ({len(data)}B), # Skip not kernel trace data.')  # ---- added code
                   continue
               logger.info(f'Receiving trace data ({len(data)}B)') # ---- added code
               out.write(data)
               out.flush()

2. Run command: python -m pymobiledevice3 developer dvt core-profile-session save core.trace --rsd xxx xxx.
3. See log.

Expected behavior In my expectation, it should continue to run until I manually stop it. And I can continuously filter out the trace information of the "swap program" to calculate FPS.

Logs I got these logs:

xxx@xxx pymobiledevice3 % sudo python -m pymobiledevice3 developer dvt core-profile-session save core.trace --rsd fd70:e645:e9b6::1 64488 -v
2023-11-24 11:48:42 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:43 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:43 xxx Tap[75648] INFO Receiving trace data (943968B), # Skip not kernel trace data.
2023-11-24 11:48:43 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:43 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:43 xxx Tap[75648] INFO Receiving trace data (445B), # Skip not kernel trace data.
2023-11-24 11:48:43 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:43 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:43 xxx Tap[75648] INFO Receiving trace data (11154B), # Skip not kernel trace data.
2023-11-24 11:48:43 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:44 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:44 xxx Tap[75648] INFO Receiving trace data (1048576B)
2023-11-24 11:48:44 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:44 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:44 xxx Tap[75648] INFO Receiving trace data (816448B)
2023-11-24 11:48:44 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:48 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:48 xxx Tap[75648] INFO Receiving trace data (16777216B)
2023-11-24 11:48:48 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:49 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:49 xxx Tap[75648] INFO Receiving trace data (5472128B)
2023-11-24 11:48:49 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:49 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:49 xxx Tap[75648] INFO Receiving trace data (444B), # Skip not kernel trace data.
2023-11-24 11:48:49 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:50 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:50 xxx Tap[75648] INFO Receiving trace data (1681216B)
2023-11-24 11:48:50 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:54 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:54 xxx Tap[75648] INFO Receiving trace data (16777216B)
2023-11-24 11:48:54 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:54 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:54 xxx Tap[75648] INFO Receiving trace data (1481728B)
2023-11-24 11:48:54 xxx Tap[75648] INFO receive_message start
2023-11-24 11:48:54 xxx Tap[75648] INFO receive_message end
2023-11-24 11:48:54 xxx Tap[75648] INFO Receiving trace data (444B), # Skip not kernel trace data.
2023-11-24 11:48:54 xxx Tap[75648] INFO receive_message start

The final log output stayed at receive_message start, dump data only lasted for ten seconds.

Thanks for help.

[doronz88]

Unfortunately that's actually the expected behavior. The python client doesn't parse the data quickly enough for the device (these are huge amounts of data) so eventually we get a socket failure after too much data is pending. Maybe some tweaks can be made to speed things up but currently that's the best we have.

[Nnnnut]

I saw this code in pymobiledevice3/services/dvt/instruments/core_profile_session_tap.py:

IDENTIFIER = 'com.apple.instruments.server.services.coreprofilesessiontap'

...

class CoreProfileSessionTap(Tap):

    ...

    def __init__(self, dvt: DvtSecureSocketProxyService, time_config: typing.Mapping, filters: typing.Set = None):

        ...

        if filters is None:
            filters = {0xffffffff}
        config = {
            'tc': [{
                'csd': 128,  # Callstack frame depth.
                'kdf2': filters,  # Kdebug filter, receive all classes.
                'ta': [[3], [0], [2], [1, 1, 0]],  # Actions.
                'tk': 3,  # Kind.
                'uuid': self.uuid,
            }],  # Triggers configs
            'rp': 100,  # Recording priority
            'bm': 0,  # Buffer mode.
        }
        super().__init__(dvt, self.IDENTIFIER, config)

It seems that the working behavior of services.coreprofilesessiontap can be changed through different config.
So I think we can try changing the output behavior of services.coreprofilesession by changing the config, such as filtering out data that I am not interested in，right?

But I don't understand the meaning of these config parameters, or maybe there are other parameters as well? Can you give me some tips on where to find detailed of config?

Thanks for help.

[doronz88]

These filters are described directly a few lines above. Unfortunately, just filtering the BSC which is the common use-case is enough to flood

[Nnnnut]

What is the BSC? Is that hexadecimal codes like those in /Applications/Xcode.app/Contents/Applications/Instruments.app/Contents/Packages/GPU.instrdst/Contents/Extensions/com.apple.metalsystrace-display.dtac/modeling-rules/rules-0001.clp?

[doronz88]

yeah it's the same concept. BSC is for BSD syscalls in general