WWDC2014 Session 714

Transcript

X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
>> Good morning,
how's everybody doing?
Enjoying the conference, I hope.
My name's Eric Clements
and I'm here to talk to you
about a new technology
we're introducing for iOS 8
and Mac OS X Yosemite
called activity tracing.
The goal of this is to hopefully
improve your ability to fix bugs
in a much quicker fashion.
So, I'm going to cover
a few topics today.
First of all, we'll go over
a little bit of a background
and why we developed this
and what our goals were.
We'll talk about some new
concepts, including things
like activities, breadcrumbs,
new concept of trace messages,
as well as some tools and
some considerations to take
into account while adopting
this new technology.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
So, let's go into
some background.
As many of you know, here
at Apple we encourage
asynchronous development very
much so because it's
very important
to have a very responsive user
interface and application.
And in doing so, we've
introduced a lot of technology
over the years, including
XPC, GCD, NSOperationsQueue,
to simplify those common tasks
that were previously complex.
In doing so we realized
that this became very
difficult to debug.
How many of you have
had problems trying
to debug your XPC and-yeah.
So, we wanted to really
find a way to improve
that with this release
and we've done a lot.
Not only in XCode with
the new Queue debugging,
but also with this new
activity tracing technology.
And you'll hear more
about this as we go along.
In addition to that, privilege
separation has, in addition,
has made that much worse because
we have another process involved
trying to separate privilege
and now you have two processes
involved that may log separately
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
and now you have two processes
involved that may log separately
and you have no way
to understand who's
causing the problem.
So, this is just another
piece of the puzzle
that has complicated our lives.
The reality is debug
tools have not kept pace.
We've done our best.
You'll see in this release,
we've done a whole lot,
as I mentioned, Queue
debugging in a session
that has happened as well.
The reality is, a lot of us
log, and I'm sure and all of you
in the room have used
this log or NSLog
or some logging mechanism to
try to debug your situation.
What we really found that that's
really not sufficient these days
because there's really not
enough context to understand
where you were and how you
got there and we really want
to find a way to
resolve that and get you
that information you really
need to diagnose the problem.
One of the diagnostic
challenges we find is
as you see going forward, you
know, when you sample a Daemon
or an XPCService, it
may look very idle,
looks like nothing's really
happening, but the reality is,
there may be two processes
or multi-processes talking
to this service that
are blocked,
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
but they also look
idle, so how do you know
that that's actually
the situation?
We really wanted to find
a way to improve this.
In addition to that, I'm
sure, if you're like me,
you probably have a desktop
that has multiple windows open,
including console, terminal,
XCode, your application
and any numerous
number of applications,
trying to understand
what's happening
at that moment in time.
We really wanted to find
a better way to do this,
so we think we developed
something.
In addition to that,
the complexity
of the OS has really
gone up over the years.
If you look at a simple
query, in this case the touch
that opendirectoryd, that
query may actually talk
to multiple daemons
in a circular fashion.
And how do you really understand
what's happening at that moment
in time because you never
know which Daemon is actually
in flight, what they're
doing and how you got there.
In addition to all this, we
also have what I call a complex
crash, where over time as an
application is being used,
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
crash, where over time as an
application is being used,
it may invoke multiple Daemons
or XPCServices and ultimately,
at the end, you have the final
event, as you see at the top,
button click that talked
to an XPCService, well,
that XPCService happened
to crash.
You may not have noticed it
in the background and all
that shows at the top
of the screen is your
query cannot be completed
at this time.
Not very helpful.
So, how do we find a
way to improve that?
So, we set out with several
goals, we really wanted
to make the additional data that
we're providing in this release,
available in a diagnostics
report you see on a daily basis,
whether that would be a
Crash Report, a spin report
or any other type of
report that we provide.
In addition to that,
we really wanted
to reduce the time you spend
guessing what, where and when.
How did I get here?
What was happening at that
moment in time and why?
You know, that's really
the biggest challenge
in this complex environment and
we really wanted to find a way
to provide you that insight.
In addition to that,
sometimes we look at problems
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
In addition to that,
sometimes we look at problems
as a single click or a single
button that caused the problem.
It's not necessarily a single
action that caused the problem,
sometimes it's the interaction
of actions over time.
Maybe there's a button click
that created a new mail,
deleted the trash and then
tried to create a new mail.
Take the pick of
your application,
it's sometimes not
just a single event,
it's actually the combination of
events that caused the problem.
So, how do we understand those
types of events over time?
Whatever we did, we knew
it had to be lightweight
and really easy to use.
So, let's look at
a Crash Report.
You can see a little
hint here, we're looking
to add some new additional
information, we're obviously
in a Crash Report, maybe
at the top we'll actually
have the events leading
up to the crash.
Down below the crashing
thread, some detailed messages
about what was happening
at that moment in time
when the crash happened.
What's really exciting
is to point
out some performance gains here
by adopting this new
activity trace mechanism,
you get some power back and
CPU back to your application
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
you get some power back and
CPU back to your application
and focus on the actual
work, versus trying
to understand what
was happening.
You see measured across
various platforms,
we've got really nice numbers.
Similarly on iOS, dramatic
difference, gives you that CPU
and power back to your
application focused on that
versus trying to understand
what was happening.
So, to cover some
terminology again
and we put these
boxes into place.
Those events I mentioned
over time, those menu clicks
and such, are what
we call activities.
An activity flows from
one process to another
and this is kind of our
scoping mechanism, so to speak.
On top of that we have a
concept of breadcrumbs,
and these are those high-level
interesting or meaningful events
that you as a developer
understand
because not every click or
every menu option is interesting
or meaningful, you get the
opportunity to actually point
out the ones that are meaningful
to you as a developer.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
out the ones that are meaningful
to you as a developer.
In addition to that,
you have trace messages
that are actually
part of this activity,
so that you actually have a
scoped view of that action
and things over time versus
a huge log to try and sift
through to understand
what was happening
at that moment in time.
And we'll show you
some great examples
of what this does for you.
We do have a new Daemon,
nothing you typically have
to worry about, but it does
come up in the background
and it will-it's the one
that handles all this
behind the scenes
and provides a diagnostic
report mechanism.
So, let's talk a little
bit about activities.
I alluded to an activity
of what it was,
but what really is an activity?
You think of an activity
as a set of work
that was triggered by an action.
As the diagram I showed before,
an application could
have done a simple query.
That query talked to
another Daemon, which talked
to other Daemons along the way.
That is a set of work that
is triggered by an action.
But I totally understand
that there are cases
where you have explicit work,
maybe you have an
initialization phase,
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
maybe you have an
initialization phase,
you're reindexing databases,
you're building a new asset
database, various reasons
that you want to xScope that,
where you can actually create
that explicitly defined sort
of work with an activity.
But what does that activity
really mean to the system?
What I mean is, it's essentially
a 64-bit identifier that's
created by the operating system.
Something you don't
have any control over,
it's automatic as
part of the API.
What's great about it is,
it's also autopropagated,
meaning it flows throughout
the system across GCD queues,
NSOperationQueues,
as well as processes.
For example, take process A
and process B, may have queues
in flight and you can see here
those-activity ID number 1
and activity ID number
2-you can see them flowing
across the process and that
happens to be XPC and GCD,
all behind the scenes,
nothing for you
to do, it's all transparent.
So, you look at activities over
time as I've showed previously
in a previous chart,
now you have a concept
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
in a previous chart,
now you have a concept
of a menu selection,
has a single activity ID
and then the next menu
select has a new activity ID.
And this is happening every
time a button is pressed
on the screen or
a click is done.
So, now you have a new
scoping mechanism that tracks
that activity across the system,
very simple concept, automatic,
nothing for you to
track directly.
Well, we obviously wanted
to make a way for you
to create these activities
and we wanted
to make sure it was easy
for you so you had nothing
to do directly unless
you wanted to.
So, we made it as
simple as possible,
we provided this automatically
through the UIKit on iOS
and the AppKit on OS X.
So, as part of every
action on the screen,
an activity is already created
on your behalf, nothing for you
to do, you just do your normal
coding as you do every day.
And we obviously have
an API to allow you
to create activities
explicitly for those cases
where you may be startup phase,
that database that I was talking
about earlier, to really scope
that information to the action
that you are trying to track.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
We have a concept of detached
activities because now
that we have this
automatically created activity,
how do you disassociate things?
Take, for example, an API
callback comes in to your query
and you realize the
database is out of sync.
How do you disassociate
that resync
or rebuild the database
from the action?
Because those are two separate
activities that you want
to track individually.
It wasn't the fact that
the person did the query
that caused the rebuild, so you
want to track those separately
and understand why
the rebuild failed
versus why the action failed.
So, here's a quick diagram
of what detached
activity looks like.
You can see activity
ID number 1,
went over across another queue
and then you had an access
you wanted to create,
it will actually create
a separate activity ID
on that next thread on whatever
work you're trying to initiate.
So, now you have two
completely individual activities
to scope this information
into your diagnostic reports.
So, how do you initiate
an activity?
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
So, how do you initiate
an activity?
So, I'm going to try to make
this a very easy API to use.
OS activity, activity name,
put some flags and a block.
One very important fact you'll
see throughout this entire
presentation, all these
strings must be constant.
We do not allow you to
pass arbitrary strings
as part of these names.
This is for various
reasons, including security,
performance and privacy.
And obviously you saw the
performance difference.
This is part of the reasons why
we get this performance gain.
We provide a flag option so
you can control the behavior.
This is when you would say I
want to detach and activity
or some other options
provided in the future.
We do provide a non-block
variant of course.
I didn't lay them all out today,
but you can look at the headers
and you can find the header,
#include os/activity.h. So,
let's talk about those
automatic generated activities.
Take a process that has the
search query about to initiate,
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
Take a process that has the
search query about to initiate,
type some characters, hit
return, AppKit's going
to actually do an OS
activity start for you
on your behalf behind
the scenes.
It'll come up with a name,
button pressed, control,
send action.
And then your actual
callback will be called just
as it is today.
And then upon return, it's going
to actually stop that scope
because it realizes that you've
returned from the function,
so the scope of this
activity is kind of returned,
but that doesn't mean the
activity itself has stopped
because, as I mentioned earlier,
these activities are flowing
across the work that
is occurring.
So, the work may
still be in flight,
but we've returned
control back to the UI
and this is just kind
of ending that scope.
As you saw previously, to create
an activity is pretty simple.
In the case here, I got a
callback doing a checkCache OS
activity initiate, flag default
and the block, very simple.
Similarly, the detached
activity-you have a searchField
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
Similarly, the detached
activity-you have a searchField
and you realize, as I mentioned
earlier, maybe the database is
out of sync, so therefore,
you want to reinitiate a
synchronize, or rebuild.
You create a new
activity and say detach it
from the current activity
because it's really
not the same operation.
I'm searching for
data and I'm going
to rebuild the database
asynchronously,
so you really want
to separate them.
So, that's activities
in a nutshell.
Most of the time you don't have
to worry about it, they're there
and if you need to
create some explicitly,
you have the option to do so.
So, let's talk about
briefly about breadcrumbs.
Breadcrumbs are essentially
a way
to label those meaningful
activities
to you, as the developer.
As I mentioned, you
understand your code,
you understand those things
that your application does
because now that we have the
automatic activities being
created from the UI, they
all look the same, you know,
you have the Send action,
you have a keypress.
Those aren't very interesting
or meaningful to you.
You actually want to hone in on
those things that are occurring
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
You actually want to hone in on
those things that are occurring
like that composed
mail, empty trash,
whatever application
you may have.
This gives us the opportunity
to see those interactions
at a microlevel.
So, as I mentioned
before, you know,
advanced essentially
isn't a particular event
that causes a problem,
it's a combination
of events that cause a problem.
So, this gives you
the opportunity
to see those over time.
You'll see this throughout,
when you see the button clicks,
now you can put an
actual name to it.
So, instead of this just
being a menu selection,
it's actually, compose
an e-mail.
Instead of being a button
click, it's a send e-mail.
Go back to our original
diagram with the activities
with activities ID's
in flight, same thing.
Now you have an activity ID with
a name as well as a breadcrumb
of those interesting
meaningful activities over time.
One thing to note
about breadcrumbs,
they're a separate kind of
ring buffer of their own.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
they're a separate kind of
ring buffer of their own.
We track the last
50 events over time.
So, you can look back in history
and see the last 50 actions
that occurred to see
what was happening
when an application
crashed or had an issue.
So, how to do you
add a breadcrumb?
Just like the previous
API, very simple,
OSactivitysetbreadcrumb
and give it a string.
This is something you
define and you control.
One key note is, this is only
supported in the main process
because it's an application
concept at a high level,
you really can't do this
from plugins or libraries.
As with the previous API,
these must be constant
strings-for both security,
privacy and performance.
Excuse me.
And as you saw previously,
same include,
#include os/activity.h. This
here is in string example
because many of its combined
callbacks for the same routine,
but in this case,
I have a search
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
but in this case,
I have a search
which actually has
an offline database.
I can actually have two
different code paths
that have two different
profiles.
I can now highlight them
separately and say, okay,
while search was initiated,
it was a button click
or as a menu selection
and this path actually,
was searching the offline cache,
which was has a different
characteristic
and different problems.
Whereas, if I'm online actually
talking to a live database,
I'll set a different
breadcrumb, because then you see
that microinteraction over time.
You understand what
the person was doing
at that moment in time.
And that's breadcrumbs in
a nutshell, simple concept,
microlevel interactions
over time.
Now, this is the most important
part and I think you're going
to find this the most exciting.
Trace messages: We provide
a new API to allow you
to add trace messages to that
activity that was created.
Uses a standard printf
file, printf format
that you're used to
on a daily basis.
It's very lightweight,
as you saw from the
performance numbers.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
What's very interesting
about this is we understand
that there's two
modes of operation.
There's a development mode,
where you're debugging
and working on an application
and there's the release mode,
the part that's shipping
on our shipping platform,
whether that be an iOS
device or a desktop.
So, we really wanted to
take that into account
when we developed this
because it's a very different
development cycle.
When there's a problem
on a production system,
you have less information
available,
but when you're actually
trying to live debug a system,
you may want to have
more information;
those debug messages,
additional detail
to understand what
was happening.
All of this is stored in
an in-memory ring buffer.
So, this is where we get
our huge performance gains.
What's very unique about this
is, unlike traditional logging,
we actually craft through
the PC of the caller.
We have the timestamp, we have
the data that was provided
as well as the sting offset
and some additional data,
including even the thread ID
that was running at the moment
that this was created.
As you can see offside here, we
actually have, the entire entry
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
As you can see offside here, we
actually have, the entire entry
for trace buffer is 64 bytes.
No matter how long
your string is,
how long your printf format
string is, it's always 64 bytes.
So, what does a trace
message look like?
As I said, looks
just like printf.
In fact, if you use printf,
you almost just do a
search and replace.
One key difference and
this is where privacy,
security come into play.
This API will only
take scalar formats.
So, you can only provide
ints, longs, doubles and such.
And you'll see the benefits
and we have some other things
that are available,
too, as well.
Part of this, of course, strings
and characters are
a privacy problem,
they're a security problem.
You know, accidentally logging
a password or a username.
Those are inappropriate to
do and this is a safeguard,
but most importantly, it
gives us the performance
that we cannot gain
with arbitrary strings.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
that we cannot gain
with arbitrary strings.
There's no way to copy an
arbitrary string efficiently
and not impact the
performance of an application.
There's another header
to include,
#include os/trace.h. Now, this
is the release trace message
that we were talking
about two loads earlier.
This is your release message.
We also have a debug
trace message.
This is when you actually
live debugging application.
Just like the release one, under
debug is the only difference,
very simple, very
straightforward.
What's great about it is the
debug messages are only saved
in the ring buffer if
you're in a debug mode.
So, a typical running
application
on a shipping device
will not record these
into the ring buffer,
saving space
for those more interesting
messages that you care
about for the application.
Additionally, in debug mode
dash, it takes more resources.
Obviously, in this case,
we actually increase
the buffer size.
Well, we're also recording
additional messages,
so we want to, we may take
more resources in this mode
so we really don't want
that on a production system.
But we obviously want you to
have that while you're trying
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
But we obviously want you to
have that while you're trying
to debug your application.
One thing to note,
there is a way
to enable what we call
the debug mode at launch.
All you do is set an
environment variable
called OSActivityModeDebug.
And then from there on, every
tool application you run
from that environment variable
will run in debug mode.
We have an additional type
of trace message
called the payload.
Now, this one's really unique
because as I mentioned earlier,
we don't support strings.
So, we want you to be able to
debug your application and such
and have additional data
that we can't provide you
in the Crash Reports.
As you can see, there's one
slight difference with this API,
it actually takes a block
as the last parameter.
It passes an XPC dictionary and
you can populate the dictionary
with any data you'd like,
anything arbitrary
can be output to this.
In this case, I'm setting a
string of the interface string
that I'm talking through.
What's great about this is
the block is only called
when it's requested.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
when it's requested.
So, in a typical
running application,
this block is skipped, but if
I'm using one of the tools,
and I say I want to see
the block because I want
to understand what's going
on, you'll get these messages,
just like you would
have otherwise
with all the other messages.
The great part is, now you
get that additional data.
I'll give you a great
example of this.
One thing to note, this does
use XPC to transmit this,
so this is extra overhead,
when this mode is enabled
because there's no simple
way to process this data,
that's why it's in
XPC dictionary,
but we do send any XPC message
across your diagnosticd.
Just like I showed
with the debug mode,
there's also an environment
variable, which you can set
to enable stream mode at launch
because sometimes you want
to understand what was happening
while the application launched,
you're going to set the similar,
OS ACTIVITY MODE=stream.
Now, this will stream all the
events from that application
to diagnosticd and
to any listeners.
So, how does this
fit into the picture?
You saw [inaudible] obviously
the trace messages fit
into that activity.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
As I mentioned earlier,
there's a ring buffer.
There's an individual
ring buffer per process,
per activity.
So, unlike the typical sys
log and the other cases
where everything goes
into one big bucket,
you have an individual ring
buffer for that activity,
in each application binary
so that one cannot
step on the other.
So, now you can get
a very different view
of your application, whether
it's your own application
or other Daemons involved.
So, let's show you what we
did for you in Crash Reports.
First of all, up top we
have our breadcrumb trail.
So, these are the events
that were occurring
up until the point that
the application crashed.
And notice the last event listed
up top or the first event listed
at the top, has an activity
ID associated with it.
This is the activity that was
in flight while it crashed.
Then down below the thread,
you actually have the
activity information.
In this case you have an ID.
You have the name that it was
created, in this case by UIkit
or AppKit called sendAction.
You have the breadcrumb.
You have how long it's been
running and any failure
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
You have how long it's been
running and any failure
that we may have detected.
Our long-term goal is to be
able to detect some situations
and inform you of that
because we can tell
that from the information.
But, most importantly,
down below,
you have all the trace messages
leading up to the crash.
And I'd like to point
out here...
[ Applause ]
As you can see, it's not just
the application that I wrote,
Query Directory, it's also
the Daemon behind the scenes.
There was nothing you had to do.
It was automatically
provided and it's
in the Crash Report
for you to look at.
This could be any number
of Daemon's involved,
any number of processes,
but you get that entire view
of why your application crashed
for the first time
directly in a Crash Report.
So, how does this exactly work?
In a crashing process, as
I showed earlier, you know,
the XPCService may have failed
while diagnosticd actually comes
up when the process fails,
the buffers from the individual
processes that are running,
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
the buffers from the individual
processes that are running,
are sent to diagnosticd along
with the activities that were
in flight and the breadcrumbs.
And this is how we get
all this information
into the diagnostic
report, all automatic,
nothing for you to do.
So, that's great for
all the general cases,
you got trace messages,
you got lots of detail,
but how do you report
those unexpected errors?
You know, you're trying to
debug a problem or you want
to highlight the fact that an
error occurred, you can also do
that with another API
called OS trace error.
It allows you to pass any
amount of data, like you saw
in the previous APIs...
[ Applause ]
All right, okay.
So, as mentioned, we
have OS trace error.
We have OS trace
error, it allows you
to provide similar format string
and whatever data
you want to output.
The only difference
about this is the fact
that it actually signals
that an error occurred.
And what does that do?
It sends those trace messages
at that time to diagnosticd
to evaluate and store, so you
can retrieve this via tools
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
to evaluate and store, so you
can retrieve this via tools
or via any other
mechanism we provide.
That's what you consider
a soft error,
but what about those
fatal errors, you know,
I'm about to crash, I got
into a state I don't
know how I got here.
We will provide an API for that
as well, cut, OS trace fault.
This may be something you
can call just before you're
about to crash.
It could be something that
you'd call to avoid a crash.
As I mentioned, it can be an
impending catastrophic failure.
This is a really bad situation,
I shouldn't be in this state,
I want to gather
this information.
The difference between this and
the error is all the buffers
from all the processes involved
are sent, just like you saw
in the crash, without
it actually crashing.
To give you a view of this, just
like you saw in the crash mode,
the difference is the
application stays up
or the Daemon stays up.
The buffers are sent and
accumulated by diagnosticd.
Simple API, you see
in this example,
we have an application main.
It's starting up some
initialization phase,
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
It's starting up some
initialization phase,
we create activity, the
initialization fails.
And this is bad, so we
initiate a fault and then exit.
In a typical situation,
which is really bad,
you crash because
that's your only way
to get information
about what failed.
Now you have a new mechanism
without actually crashing.
And I'll show you
what this gets you.
With all this said, we should
talk about what's supported
as far as trace messages.
For example, this is a perfectly
valid good trace message.
Similarly, I can pass other
types whether they be longs
or shorts and such.
You can see various forms.
You can even pass a pointer
because sometimes a pointer
to us is a correlation
point and, you know,
maybe it's a connection
you're trying to follow
and understand that's
being shared
across multiple activities.
You can even output floats.
In this case, I can output
how many clients I had
and the average time they
were connected to that.
And that's additional data you
didn't have in your application
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
And that's additional data you
didn't have in your application
at the time it crashed.
So, let's talk about
unsupported trace messages.
As I mentioned earlier,
strings are not supported.
So, well, how do
we protect that?
Well, you can try to trace
one, but you're going
to get unsupported
string in the output,
so it doesn't break anything,
so if you actually do it,
it's not going to hurt you,
but you won't ever see
the data out of it.
Now, it's partially because of
the way the mechanism is built.
There's basically no
way to provide a string
because we don't copy
data out of the binary.
But, providing a string doesn't
break valid data-in this case,
I can still pass the UID and you
can see the password will not be
admitted, you get
unsupported string.
So, you can mix and
match, it doesn't hurt you.
Just be aware that
it's not supported.
Along the same lines,
characters are not supported
because we don't want
to be accidentally outputting
passwords with characters.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
to be accidentally outputting
passwords with characters.
So, obviously we have limits.
Format string cannot
exceed 100 characters.
That's a pretty long
format string,
so hopefully that's more
than enough for you.
One thing to note, the trace
message content will truncate,
so if you put too much
data or too long a string,
it's going to truncate
it in the output.
This is expected behavior.
Initially we're only
providing you seven parameters,
so you can output
up to seven scalars.
One very important note,
these trace messages
and the buffers may vary
by platform and mode.
As I mentioned earlier
in your debug mode,
we may provide a much
larger ring buffer.
Whereas, when you're not in a
debug mode, it's much smaller,
or maybe on a particular
iOS device, where we're low
on memory, so we don't
enable it at all.
Just be aware there are limits.
We can't enable it everywhere
and it may vary by
that by platform.
So, let's do a quick demo.
So, I have an application
running here, Query Directory.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
So, I have an application
running here, Query Directory.
I'm just going to
search for something
that I know is in admin.
Okay, you'll see down
here, there's the result.
Nothing bad happened.
Try it again and I'll do a
NSOperatationQueue mode instead,
still no failure.
Now I'm going to type something
I know that will cause a crash.
Now, you see in the
Crash Report,
you have that breadcrumb trail
that I was talking about.
You see the last operation
queue that was in flight,
the activity ID and if I scroll
down to the crashing thread,
you can see this was the
NSOperationQueue that was
in flight, but now you've
got all this new info
that you didn't have
before, the activity
and all the trace messages
leading up to the event.
In this case, you can
see query directory
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
In this case, you can
see query directory
and opendirectoryd involved.
Exciting?
[ Applause ]
I know I'm excited because
this has always been a problem
for me.
That's just a quick demo,
so you can see it for real.
So, it's great, but what
about debugger support?
Well, it's great for
having the Crash Reports
and the string reports, but
when you're really working
on a problem, how do
you see this live?
Well, we made it
built-in to the debugger.
So you can actually see the
activity that's on a thread,
as well as any trace
messages for that activity.
This is a very powerful
mechanism.
In the case of lldb you can
see here, I have a thread
that was crashing, I
can type thread info.
As part of that thread info, I
have the activity name that was
in flight, how many
messages it accumulated
and down below it you have all
that detail in the debugger.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
and down below it you have all
that detail in the debugger.
So, instead of switching
between console and terminal,
you can just stay in your
debugger, output those messages
and say, oh, this is how I got
here and why did this happen?
Click it here so you
can see that activity,
the current breadcrumb
and those trace messages.
So, let's demo that
because that's the fun part.
And if the demo gods are good
to me or I'm good to them,
we'll have a demo that works.
So, let's do the
same as I did before.
I'll search and you
can see the result.
I'll do an OperationQueue,
and let's crash.
Now, in the same window I
can say thread info and,
of course, it didn't work.
[ Background Sounds ]
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
[ Background Sounds ]
So, there's that same info.
[ Applause ]
[ Background Sounds ]
So, you can try this with
various combinations,
obviously this works with
all of our infrastructure,
which is really exciting
because it works with XPC,
GCD and NSOperationQueue
and obviously the tools.
So, we talked about
what we have,
let's talk about a new tool
we provided, ostraceutil.
This will allow you to watch
that live streaming I was
talking about earlier, right?
All that XPC dictionary
and additional data
that you didn't have
in the Crash Report.
You'll be able to watch
for faults and errors
across the system or by process.
So, while you're
debugging the application,
you can actually say ostraceutil
watch fault application.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
you can actually say ostraceutil
watch fault application.
And you'll see the faults that
your application are generating
without having to enable
any logs and having
to do any extra effort.
In addition to that, you
can actually look what kind
of activities and trace
messages the binary has,
whether it be your binary
to check it before it goes
out into production, or to look
at what other processes are
providing in this mechanism.
So, you see a complete view
of your development cycle.
This is a look at
the live stream.
In this case, ostraceutilwatch
Query Directory, very simple.
You'll notice down here in
the middle, you actually have
that payload I was
talking about.
So, even though we don't
support strings and characters,
you can put whatever
you like here.
It could be a binary block,
it could be strings, data.
You still get it so you
can still do your job
and debug your application.
And in this case, you can
see the case I've typed
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
to crash the app
every time is Z.
I got the Z as part
of the query string.
Similarly, with faults.
This is kind of fun because
I can actually watch faults
across the entire system.
Inthis case,
ostraceutilwatchfaults.
And you can see the Query
Directory triggered a fault
because something bad happened.
You get the Image uuid,
the PID and the path.
You'll see the breadcrumbs
and the timestamps
with those breadcrumbs.
You'll see that same
activity information as well
as the trace messages.
So, for the first time without
enabling any additional logging,
you can see this data
while you're working
on your application.
So, what are some things
to take into consideration?
Privacy-we're very
concerned about privacy.
So, be very conscious
about what you're tracing
when you're adding
trace messages.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
when you're adding
trace messages.
Never trace information
about a user device.
There's a session at 2:00.
If you don't get a chance to see
it, please take a look at it,
there's a privacy session
on both OS X and iOS.
I think we have one every year
and there's one again
today at 2:00.
One thing I'd like to note
is we've done our best to try
to do what we call with
propagation failures.
Because this mechanism is
automatic, there are cases
where a custom queuing mechanism
is built into an application.
And that little connection
is missing.
So, even though the work
happened, we don't have the idea
of the trace message
or the activity.
And what ends up happening
is you get two-thirds
of the picture.
We've done our best
to cover the bases
and get these where we can.
Just be aware that, you know,
we can't catch them all.
As you see from the
chart, this is supported
in our diagnostic tools,
OS X Yosemite supports
in Crash Reports, Spin
Reports, Stackshots and lldb.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
in Crash Reports, Spin
Reports, Stackshots and lldb.
Please note that
the lldb support
that I showed you onstage
is not active in your seat,
but look forward to it in
a future seat for Yosemite,
but it is active for iOS 8.
So, you can actually look at
your Crash Reports and lldb
to get this information.
So, in summary, why
use activity tracing?
Well, I think there is a lot of
good reasons, as you may tell
from the presentation.
It's already included in
your diagnostic reports.
No additional work.
No more enable logging.
No more turn on this
log or this messaging.
It's all part of your diagnostic
report right out of the gate.
We have built-in debugger
support, so you don't have
to leave your debugger and
figure out what was happening.
It works on both iOS and OS X,
extremely fast and efficient,
integrated with GCD, XPC,
NSOperationQueue and Foundation.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
And as I alluded to, it
captures additional data
that traditional logging
doesn't-the caller of the API,
the thread it was running on and
other additional information.
But most exciting to me,
is these trace messages are
actually scoped to the action
that caused the problem.
So, instead of sifting
through tons and tons of logs,
through different processes to
understand what was happening,
you finally have the information
right in front of you
at the time it happened.
For more information,
please contact Paul
Danbold our Evangelist.
We don't have official
documentation,
as you can see this
is a very simple API,
but there are headers and manned
pages for them, please feel free
to take a look at them
and please contact
the developer forums.
Some related sessions-some of
these have already occurred,
but I do encourage you to go to
the privacy session if you can
at 2:00, which of
course conflicts
with the diagnostics
performance in GCD and XPC,
but both of those
are very important.
I would suggest taking
a look at them.
X-TIMESTAMP-MAP=MPEGTS:181083,LOCAL:00:00:00.000
I would suggest taking
a look at them.
Thank you.
[ Applause ]