<kdebug-string-from> and dyld

I am attempting to analyze the amount of time individual images are taking to load into my iPhone app. dyld has some fun environment variables for seeing the overall time, but tracking individual libraries is not possible (As far as I know). I looked into the dyld source code and found Tracing.h which led me to believe I could put together a custom instrument to track image loading. Here is the schema I used:


  <ktrace-interval-schema>
    <id>com-google-dyld-map-image-schema</id>
    <title>dyld map image</title>
    <start-pattern>
      <class>31</class>
      <subclass>7</subclass>
      <code>2</code>
      <function>1</function>
      <arg1>?id</arg1>
      <arg2>?afilepath</arg2>
    </start-pattern>
    <end-pattern>
      <class>31</class>
      <subclass>7</subclass>
      <code>2</code>
      <function>2</function>
      <arg1>?id</arg1>
    </end-pattern>
    <start-column>
      <mnemonic>start</mnemonic>
      <title>Start</title>
      <type>start-time</type>
    </start-column>
    <duration-column>
      <mnemonic>duration</mnemonic>
      <title>Duration</title>
      <type>duration</type>
    </duration-column>
    <column>
      <mnemonic>id</mnemonic>
      <title>id</title>
      <type>uint64</type>
      <expression>?id</expression>
    </column>
    <column>
      <mnemonic>path</mnemonic>
      <title>path</title>
      <type>file-path</type>
      <kdebug-string-from>?afilepath</kdebug-string-from>
    </column>
    <column>
      <mnemonic>path-id</mnemonic>
      <title>path-id</title>
      <type>kdebug-string</type>
      <expression>?afilepath</expression>
    </column>
  </ktrace-interval-schema>


and here is the table/graph/list:


      <create-table>
        <id>timings-table</id>
        <schema-ref>com-google-dyld-map-image-schema</schema-ref>
      </create-table>
      <graph>
        <title>Image Mapping Trace</title>
        <lane>
          <title>Image Mappings</title>
          <table-ref>timings-table</table-ref>
          <plot>
            <value-from>path</value-from>
          </plot>
        </lane>
      </graph>
      <list>
        <title>Image Mapping Times</title>
        <table-ref>timings-table</table-ref>
        <column>start</column>
        <column>duration</column>
        <column>path</column>
        <column>path-id</column>
      </list>
    </instrument>


So when I run this in instruments, I get:

https://imgur.com/a/zsoJvkI

Notice that the path is "n/a"


I look in the Instruments Inspector for kdebug-strings and see:

https://imgur.com/a/Ca1ASqF


I'm assuming I am getting N/A because there are two strings (one filled and one blank) tied to each of the kdebug string IDs. Is this a valid assumption?


I went looking in the dyld timing code, and it appears Tracing.h that kdebug_trace_string is being called both to set and clear the string. I'm guessing that we never want kdebug_trace_strings cleared.


Is there anyway for me to get my image name to appear correctly?


The complete source for my instrument is here.


Cheers,

Dave


Accepted Reply

Oh, that's a bummer... I think what's happening is that we look up the string when the record is being written (i.e. during the handling of the end event), and by that time, the string has been "cleared". The string would have to stick around until after the end event was sent, or we need to change the generator (those "ktrace-interval-schema" elements translate into CLIPS at .instrdst build time) to tuck away the resolved string at the start event handler.


If that's really what's happening, then it's a good enhancement request radar if you'd like to file it.

Replies

Oh, that's a bummer... I think what's happening is that we look up the string when the record is being written (i.e. during the handling of the end event), and by that time, the string has been "cleared". The string would have to stick around until after the end event was sent, or we need to change the generator (those "ktrace-interval-schema" elements translate into CLIPS at .instrdst build time) to tuck away the resolved string at the start event handler.


If that's really what's happening, then it's a good enhancement request radar if you'd like to file it.

Sorry, you did ask "Is there anyway", and I didn't answer that fully. Yes, there is a way (without having to wait for a patch from Apple) but you'd need to write your own CLIPS modeler. The generated .instrdst contains the CLIPS source code that we generate, which could act as a bootstrap to get your started, but you know... generated code isn't exactly clean or elegant. The goal would be to capture the start event, extract everything you need to write the record, including the string, and then write the record at the end event and retract the facts you asserted during the open event.


The tail end of our WWDC 2018 presentation on building custom instruments contains the basics on how you might do it, if you really want to work around it in the short term.

Thanks... I'll look into the modeler, but I must admit it's pretty intimidating 🙂


I filed the radar: 47128069


Cheers,

Dave