Media Nodes Made Easy (Well, Easier...)

DEVELOPERS' WORKSHOP: Media Nodes Made Easy (Well, Easier...)
By Christopher Tate (ctate@be.com)

"Developers' Workshop" is a weekly feature that provides answers to our developers' questions, or topic requests. To submit a question, visit

http://www.be.com/developers/suggestion_box.html.

As anyone who sat through the Node Track of the recent Be Developers Conference can attest, writing Media Kit nodes is a complex task. Be's engineering team has been hard at work extending the Media Kit APIs to simplify node construction; similarly, DTS has been developing tools developers can use to debug their own BMediaNodes. This week's article introduces a tool for analyzing the behavior of any BBufferProducer node or node chain: the LoggingConsumer. Designed to work with the Genki/6 beta release (I told you the APIs were under construction!), this node tracks the behavior of its input stream, logging a trace of all activity to a file for post-mortem analysis.

Before I discuss what exactly the LoggingConsumer does, here's the URL to download it, so that you can follow along at home:

<ftp://ftp.be.com/pub/samples/media kit/LoggingConsumer.zip >

So, What Is This "LoggingConsumer" Anyway?

As BBufferConsumers go, LoggingConsumer is pretty simple: it doesn't manipulate its input buffers in any way, it doesn't talk to hardware, and it doesn't pass buffers downstream -- it sits at the end of the node chain. It has a single input, which can accept any kind of data. You, the developer, connect to a node or node chain that you're interested in, point it at an output file entry ref, and voila! Useful information about buffer flow and internode handshaking is recorded for later interpretation.

The LoggingConsumer node serves two purposes: it produces a trace of node activity, for the purpose of debugging producers and producer/filter node chains; and it serves as a clean example of BBufferConsumer structure and behavior. The node tries to do everything "right," and is commented to help you understand what's going on at all points in the code. The node uses the latest and greatest BMediaEventLooper class. It publishes a set of controllable parameters via a BParameterWeb, and handles the B_MEDIA_PARAMETERS buffer type for changing those parameters. It reports late buffers to the producer, and reports latency changes as well. In short, it demonstrates pretty much all of the major functionality that a BBufferConsumer has to worry about.

So, How's It Work?

In order to preserve the realtime behavior of a proper Media Kit node, the LoggingConsumer doesn't do any disk access from within its main BMediaNode control thread. Instead, it spawns a separate thread to write logged messages to disk, and passes messages to that thread via a kernel port. The LogWriter class encapsulates this pattern, managing the non-realtime thread and message port transparently to the LoggingConsumer node implementation.

The LoggingConsumer itself is another example of using the new BMediaEventLooper class to handle most of the nitty-gritty details of being a node. Because it does very little actual media-related processing, it's a pretty clear illustration of the organization we recommend that nodes use. The example application, which hooks the LoggingConsumer up to an audio file reader, also uses a simple "Connection" structure to illustrate the necessary bookkeeping for setting up and tearing down the connection between two nodes.

What's It Give Me?

Lots. Every virtual entry point a media node has generates an entry in the log file (with the minor exception of GetNextInput() and DisposeInputCookie() -- and you can add support for these easily). Log entries are marked with the current real time (i.e., system_time()) when they are generated, as well as the current time according to the LoggingConsumer's time source. Some operations log additional information, as well. For example, when a buffer is received, the logged message will indicate whether it is already late. When a buffer is handled (i.e., popped off of the BMediaEventLooper's event queue) the buffer's performance time is logged, as well as how early the buffer was handled. That "offset" needs to lie within the node's scheduling latency; if it doesn't, the buffer is late. The node also maintains a count of late buffers, so your testing application can follow what's happening.

LoggingConsumer is a BControllable, too, and you can manipulate certain aspects of its behavior while it's running. In particular, you can adjust its latency on the fly. Reacting to latency changes is one of the trickier aspects of BBufferProducer nodes, so having this facility in the buffer consumer lets you test a producer in a reliable, repeatable fashion. Future versions of the LoggingConsumer will have other controllable features as well, such as the ability to change media formats on the fly.

Here's an example of what you get in the log file:

>     LOG_REGISTERED           : realtime = 240371553910, perftime = 262890
>     LOG_ACCEPT_FORMAT        : realtime = 240371564256, perftime = 2331465007
>     LOG_CONNECTED            : realtime = 240371564475, perftime = 2331465228
>     LOG_PREROLL              : realtime = 240371565650, perftime = 2331466400
>     LOG_START                : realtime = 240372603671, perftime = 2332503192
>     LOG_START_HANDLED        : realtime = 240372603726, perftime = 2332503245
>     LOG_PRODUCER_DATA_STATUS : realtime = 240372604250, perftime = 2332503773
>     LOG_DATA_STATUS_HANDLED  : realtime = 240372604285, perftime = 2332503809
>             status = 2
>     LOG_BUFFER_RECEIVED      : realtime = 240372604448, perftime = 2332503969
>             start = 2332553303, offset = -5666
>             Buffer received *LATE*
>     LOG_BUFFER_HANDLED       : realtime = 240372604481,  perftime = 2332504002
>             start = 2332553303, offset = -701
>             Buffer handled *LATE*
>     LOG_BUFFER_RECEIVED      : realtime = 240372604687, perftime = 2332504209
>     LOG_BUFFER_RECEIVED      : realtime = 240372605766, perftime = 2332505279
>     LOG_BUFFER_RECEIVED      : realtime = 240372606497, perftime = 2332506016
>     LOG_BUFFER_RECEIVED      : realtime = 240372607226, perftime = 2332506744
>     LOG_BUFFER_RECEIVED      : realtime = 240372608545, perftime = 2332508060
>     LOG_BUFFER_RECEIVED      : realtime = 240372624297, perftime = 2332523788
>     LOG_BUFFER_HANDLED       : realtime = 240372638948, perftime = 2332538420
>             start = 2332593303, offset = 4876
>     LOG_BUFFER_RECEIVED      : realtime = 240372678548, perftime = 2332577979
>     LOG_BUFFER_HANDLED       : realtime = 240372678965, perftime = 2332578395
>             start = 2332633303, offset = 4906

The "realtime" field is the current system time() at the moment the message was logged, and "perftime" is the LoggingConsumer's idea of the current time according to its time source (i.e., the current performance time). As you can see, the node is registered, then the format negotiation with the producer occurs, the node is Preroll()ed, then it's Start()ed. When the producer node was started it sent a ProducerDataStatus() message, then began sending buffers. Note that there is a distinction between the buffer's receipt in BufferReceived() and its eventual handling in HandleEvent(). Also note that given our stated scheduling latency of 5000 microseconds, the first buffer was sent too late for the LoggingConsumer to handle in a timely manner -- information to be communicated to whoever wrote this particular BBufferProducer node!

The LogWriter class can easily be adapted to log other sorts of messages. Just add your own custom message codes to the log_what enum in LogWriter.h, string translations for them to the log_what_to_string() function, and appropriate handling in LogWriter::HandleMessage(). If you need to pass custom information in the log message, add a new variant to the union declared in the log_message struct.

If you're developing BBufferProducer nodes, this class will help you debug them. If you're developing BBufferConsumers, this node will show you how to structure your code. And if you're just writing Media Kit applications, this node gives you an easy way to tell whether you've set up the rest of the node chain correctly. Any way you slice it, LoggingConsumer is a must-have component in any Media Kit development suite!