src/apps/cortex/addons/LoggingConsumer/article.html

   1 <HTML>
   2 <HEAD>
   3 <TITLE>Media Nodes Made Easy (Well, Easier...)</TITLE>
   4 </HEAD>
   5 <BODY BGCOLOR="0xFFFFFF">
   6 <!-- Developer's Workshop -->
   7
   8 <FONT SIZE=+1><B><A NAME="Workshop"></A>DEVELOPERS' WORKSHOP: Media Nodes Made Easy (Well, Easier...)</B></FONT>
   9 <br><B>By Christopher Tate (<A HREF="mailto:ctate@be.com">ctate@be.com</A>)</B><BR>
  10
  11
  12 <P><FONT="-1">"Developers' Workshop" is a weekly feature that provides
  13 answers to our developers' questions, or topic requests.
  14 To submit a question, visit
  15 <P><A HREF="http://www.be.com/developers/suggestion_box.html">http://www.be.com/developers/suggestion_box.html</A>.
  16
  17 <P>
  18 <P>As anyone who sat through the Node Track of the recent Be
  19 Developers Conference can attest, writing Media Kit nodes
  20 is a complex task. Be's engineering team has been hard at
  21 work extending the Media Kit APIs to simplify node
  22 construction; similarly, DTS has been developing tools
  23 developers can use to debug their own BMediaNodes. This
  24 week's article introduces a tool for analyzing the behavior
  25 of any BBufferProducer node or node chain: the
  26 LoggingConsumer. Designed to work with the Genki/6 beta
  27 release (I told you the APIs were under construction!),
  28 this node tracks the behavior of its input stream, logging
  29 a trace of all activity to a file for post-mortem analysis.
  30
  31
  32 <P>Before I discuss what exactly the LoggingConsumer does,
  33 here's the URL to download it, so that you can follow along
  34 at home:
  35
  36
  37 <P>&lt;<a href="ftp://ftp.be.com/pub/samples/media kit/LoggingConsumer.zip">ftp://ftp.be.com/pub/samples/media kit/LoggingConsumer.zip
  38 </a>&gt;
  39
  40
  41 <P>
  42 <b>So, What Is This &quot;LoggingConsumer&quot; Anyway?</b>
  43
  44
  45 <P>As BBufferConsumers go, LoggingConsumer is pretty simple: it
  46 doesn't manipulate its input buffers in any way, it doesn't
  47 talk to hardware, and it doesn't pass buffers downstream --
  48 it sits at the end of the node chain. It has a single input,
  49 which can accept any kind of data. You, the developer, connect
  50 to a node or node chain that you're interested in, point it at
  51 an output file entry ref, and voila! Useful information about
  52 buffer flow and internode handshaking is recorded for later
  53 interpretation.
  54
  55
  56 <P>The LoggingConsumer node serves two purposes: it produces a
  57 trace of node activity, for the purpose of debugging
  58 producers and producer/filter node chains; and it serves as
  59 a clean example of BBufferConsumer structure and behavior.
  60 The node tries to do everything &quot;right,&quot; and is commented to
  61 help you understand what's going on at all points in the
  62 code. The node uses the latest and greatest
  63 BMediaEventLooper class. It publishes a set of controllable
  64 parameters via a BParameterWeb, and handles the
  65 B MEDIA PARAMETERS buffer type for changing those
  66 parameters. It reports late buffers to the producer, and
  67 reports latency changes as well. In short, it demonstrates
  68 pretty much all of the major functionality that a
  69 BBufferConsumer has to worry about.
  70
  71
  72 <P>
  73 <b>So, How's It Work?</b>
  74
  75
  76 <P>In order to preserve the realtime behavior of a proper Media
  77 Kit node, the LoggingConsumer doesn't do any disk access
  78 from within its main BMediaNode control thread. Instead, it
  79 spawns a separate thread to write logged messages to disk,
  80 and passes messages to that thread via a kernel port. The
  81 LogWriter class encapsulates this pattern, managing the
  82 non-realtime thread and message port transparently to the
  83 LoggingConsumer node implementation.
  84
  85
  86 <P>The LoggingConsumer itself is another example of using the
  87 new BMediaEventLooper class to handle most of the
  88 nitty-gritty details of being a node. Because it does very
  89 little actual media-related processing, it's a pretty clear
  90 illustration of the organization we recommend that nodes
  91 use. The example application, which hooks the
  92 LoggingConsumer up to an audio file reader, also uses a
  93 simple &quot;Connection&quot; structure to illustrate the necessary
  94 bookkeeping for setting up and tearing down the connection
  95 between two nodes.
  96
  97
  98 <P>
  99 <b>What's It Give Me?</b>
 100
 101
 102 <P>Lots. Every virtual entry point a media node has generates
 103 an entry in the log file (with the minor exception of
 104 GetNextInput() and DisposeInputCookie() -- and you can add
 105 support for these easily). Log entries are marked with the
 106 current real time (i.e., system time()) when they are
 107 generated, as well as the current time according to the
 108 LoggingConsumer's time source. Some operations log
 109 additional information, as well. For example, when a buffer
 110 is received, the logged message will indicate whether it is
 111 already late. When a buffer is handled (i.e., popped off of
 112 the BMediaEventLooper's event queue) the buffer's
 113 performance time is logged, as well as how early the buffer
 114 was handled. That &quot;offset&quot; needs to lie within the node's
 115 scheduling latency; if it doesn't, the buffer is late. The
 116 node also maintains a count of late buffers, so your testing
 117 application can follow what's happening.
 118
 119
 120 <P>LoggingConsumer is a BControllable, too, and you can
 121 manipulate certain aspects of its behavior while it's
 122 running. In particular, you can adjust its latency on the
 123 fly. Reacting to latency changes is one of the trickier
 124 aspects of BBufferProducer nodes, so having this facility in
 125 the buffer consumer lets you test a producer in a reliable,
 126 repeatable fashion. Future versions of the LoggingConsumer
 127 will have other controllable features as well, such as the
 128 ability to change media formats on the fly.
 129
 130
 131 <P>Here's an example of what you get in the log file:
 132
 133 <blockquote><pre>
 134 LOG REGISTERED           : realtime = 240371553910, perftime = 262890
 135 LOG ACCEPT FORMAT        : realtime = 240371564256, perftime = 2331465007
 136 LOG CONNECTED            : realtime = 240371564475, perftime = 2331465228
 137 LOG PREROLL              : realtime = 240371565650, perftime = 2331466400
 138 LOG START                : realtime = 240372603671, perftime = 2332503192
 139 LOG START HANDLED        : realtime = 240372603726, perftime = 2332503245
 140 LOG PRODUCER DATA STATUS : realtime = 240372604250, perftime = 2332503773
 141 LOG DATA STATUS HANDLED  : realtime = 240372604285, perftime = 2332503809
 142         status = 2
 143 LOG BUFFER RECEIVED      : realtime = 240372604448, perftime = 2332503969
 144         start = 2332553303, offset = -5666
 145         Buffer received *LATE*
 146 LOG BUFFER HANDLED       : realtime = 240372604481,  perftime = 2332504002
 147         start = 2332553303, offset = -701
 148         Buffer handled *LATE*
 149 LOG BUFFER RECEIVED      : realtime = 240372604687, perftime = 2332504209
 150 LOG BUFFER RECEIVED      : realtime = 240372605766, perftime = 2332505279
 151 LOG BUFFER RECEIVED      : realtime = 240372606497, perftime = 2332506016
 152 LOG BUFFER RECEIVED      : realtime = 240372607226, perftime = 2332506744
 153 LOG BUFFER RECEIVED      : realtime = 240372608545, perftime = 2332508060
 154 LOG BUFFER RECEIVED      : realtime = 240372624297, perftime = 2332523788
 155 LOG BUFFER HANDLED       : realtime = 240372638948, perftime = 2332538420
 156         start = 2332593303, offset = 4876
 157 LOG BUFFER RECEIVED      : realtime = 240372678548, perftime = 2332577979
 158 LOG BUFFER HANDLED       : realtime = 240372678965, perftime = 2332578395
 159         start = 2332633303, offset = 4906
 160 </pre></blockquote>
 161
 162 <P>The &quot;realtime&quot; field is the current system time() at the
 163 moment the message was logged, and &quot;perftime&quot; is the
 164 LoggingConsumer's idea of the current time according to its
 165 time source (i.e., the current performance time). As you can
 166 see, the node is registered, then the format negotiation
 167 with the producer occurs, the node is Preroll()ed, then it's
 168 Start()ed. When the producer node was started it sent a
 169 ProducerDataStatus() message, then began sending buffers.
 170 Note that there is a distinction between the buffer's
 171 receipt in BufferReceived() and its eventual handling in
 172 HandleEvent(). Also note that given our stated scheduling
 173 latency of 5000 microseconds, the first buffer was sent too
 174 late for the LoggingConsumer to handle in a timely manner --
 175 information to be communicated to whoever wrote this
 176 particular BBufferProducer node!
 177
 178
 179 <P>The LogWriter class can easily be adapted to log other sorts
 180 of messages. Just add your own custom message codes to the
 181 log what enum in LogWriter.h, string translations for them
 182 to the log what to string() function, and appropriate
 183 handling in LogWriter::HandleMessage(). If you need to pass
 184 custom information in the log message, add a new variant to
 185 the union declared in the log message struct.
 186
 187
 188 <P>If you're developing BBufferProducer nodes, this class will
 189 help you debug them. If you're developing BBufferConsumers,
 190 this node will show you how to structure your code. And if
 191 you're just writing Media Kit applications, this node gives
 192 you an easy way to tell whether you've set up the rest of
 193 the node chain correctly. Any way you slice it,
 194 LoggingConsumer is a must-have component in any Media Kit
 195 development suite!
 196 </HTML>