xref: /haiku/src/apps/cortex/addons/LoggingConsumer/LoggingConsumer.cpp (revision 2cba2d5642ee902f1ac72ec6ce2fa383516a3f35)
1 /*
2  * Copyright 1991-1999, Be Incorporated.
3  * Copyright (c) 1999-2000, Eric Moon.
4  * All rights reserved.
5  *
6  * Redistribution and use in source and binary forms, with or without
7  * modification, are permitted provided that the following conditions
8  * are met:
9  *
10  * 1. Redistributions of source code must retain the above copyright
11  *    notice, this list of conditions, and the following disclaimer.
12  *
13  * 2. Redistributions in binary form must reproduce the above copyright
14  *    notice, this list of conditions, and the following disclaimer in the
15  *    documentation and/or other materials provided with the distribution.
16  *
17  * 3. The name of the author may not be used to endorse or promote products
18  *    derived from this software without specific prior written permission.
19  *
20  * THIS SOFTWARE IS PROVIDED BY THE AUTHOR "AS IS" AND ANY EXPRESS OR
21  * IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
22  * OF TITLE, NON-INFRINGEMENT, MERCHANTABILITY AND FITNESS FOR A PARTICULAR
23  * PURPOSE ARE DISCLAIMED.  IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY
24  * DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
25  * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
26  * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED
27  * AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR
28  * TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
29  * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
30  */
31 
32 
33 // LoggingConsumer.cpp
34 
35 #include "LoggingConsumer.h"
36 #include "LogWriter.h"
37 #include <media/MediaRoster.h>
38 #include <media/TimeSource.h>
39 #include <media/ParameterWeb.h>
40 #include <media/Buffer.h>
41 #include <kernel/OS.h>
42 #include <stdio.h>
43 #include <string.h>
44 
45 // e.moon [11jun99]
46 #include <Catalog.h>
47 #include <Debug.h>
48 
49 #undef B_TRANSLATION_CONTEXT
50 #define B_TRANSLATION_CONTEXT "CortexAddOnsLoggingConsumer"
51 
52 // id's of the node's BParameters
53 const int32 INPUT_NULL_PARAM = 1;
54 const int32 LATENCY_PARAM = 2;
55 const int32 OUTPUT_NULL_PARAM = 3;
56 const int32 CPU_NULL_PARAM = 11;
57 const int32 CPU_SPIN_PARAM = 12;
58 const int32 PRIO_NULL_PARAM = 21;
59 const int32 PRIORITY_PARAM = 22;
60 
61 // build the LoggingConsumer's BParameterWeb
build_parameter_web()62 static BParameterWeb* build_parameter_web()
63 {
64 	BParameterWeb* web = new BParameterWeb;
65 
66 	BParameterGroup* mainGroup = web->MakeGroup(
67 		B_TRANSLATE("LoggingConsumer parameters"));
68 	BParameterGroup* group = mainGroup->MakeGroup(
69 		B_TRANSLATE("Latency control"));
70 	BParameter* nullParam = group->MakeNullParameter(INPUT_NULL_PARAM,
71 		B_MEDIA_NO_TYPE, B_TRANSLATE("Latency"), B_GENERIC);
72 	BParameter* latencyParam = group->MakeContinuousParameter(LATENCY_PARAM,
73 		B_MEDIA_NO_TYPE, "", B_GAIN, "ms", 5, 100, 5);
74 	nullParam->AddOutput(latencyParam);
75 	latencyParam->AddInput(nullParam);
76 
77 	group = mainGroup->MakeGroup(B_TRANSLATE("CPU percentage"));
78 	nullParam = group->MakeNullParameter(CPU_NULL_PARAM, B_MEDIA_NO_TYPE,
79 		B_TRANSLATE("CPU spin percentage"), B_GENERIC);
80 	BContinuousParameter* cpuParam = group->MakeContinuousParameter(
81 		CPU_SPIN_PARAM, B_MEDIA_NO_TYPE, "",
82 		B_GAIN, B_TRANSLATE("percent"), 5, 80, 5);
83 	nullParam->AddOutput(cpuParam);
84 	cpuParam->AddInput(nullParam);
85 
86 	group = mainGroup->MakeGroup(B_TRANSLATE("Priority"));
87 	nullParam = group->MakeNullParameter(PRIO_NULL_PARAM, B_MEDIA_NO_TYPE,
88 		B_TRANSLATE("Thread priority"), B_GENERIC);
89 	BDiscreteParameter* prioParam = group->MakeDiscreteParameter(PRIORITY_PARAM,
90 		B_MEDIA_NO_TYPE, "", B_GENERIC);
91 	prioParam->AddItem(5, "B_LOW_PRIORITY");
92 	prioParam->AddItem(10, "B_NORMAL_PRIORITY");
93 	prioParam->AddItem(15, "B_DISPLAY_PRIORITY");
94 	prioParam->AddItem(20, "B_URGENT_DISPLAY_PRIORITY");
95 	prioParam->AddItem(100, "B_REAL_TIME_DISPLAY_PRIORITY");
96 	prioParam->AddItem(110, "B_URGENT_PRIORITY");
97 	prioParam->AddItem(120, "B_REAL_TIME_PRIORITY");
98 
99 	return web;
100 }
101 
102 // --------------------
103 // LoggingConsumer class implementation
LoggingConsumer(const entry_ref & logFile,BMediaAddOn * pAddOn)104 LoggingConsumer::LoggingConsumer(
105 	const entry_ref& logFile,
106 	BMediaAddOn* pAddOn)
107 
108 	:	BMediaNode("LoggingConsumer"),
109 		BBufferConsumer(B_MEDIA_UNKNOWN_TYPE),
110 		BControllable(),
111 		BMediaEventLooper(),
112 		mLogRef(logFile),
113 		mWeb(NULL),
114 		mLateBuffers(0),
115 		mLatency(50 * 1000),		// default to 50 milliseconds
116 		mSpinPercentage(0.10),		// default to spinning 10% of total latency
117 		mPriority(B_URGENT_DISPLAY_PRIORITY),		// !!! testing; will be B_REAL_TIME_PRIORITY for release
118 		mLastLatencyChange(0),
119 		mLastSpinChange(0),
120 		mLastPrioChange(0),
121 		m_pAddOn(pAddOn)
122 {
123 	// spin off the logging thread
124 	mLogger = new LogWriter(logFile);
125 
126 	// parameter-web init moved to NodeRegistered()
127 	// e.moon [11jun99]
128 }
129 
~LoggingConsumer()130 LoggingConsumer::~LoggingConsumer()
131 {
132 	PRINT(("~LoggingConsumer()\n"));
133 	BMediaEventLooper::Quit();
134 // ahem:
135 // "Once you've called BControllable::SetParameterWeb(), the node takes
136 //  responsibility for the parameter web object and you shouldn't delete it. "
137 //	SetParameterWeb(NULL);
138 //	delete mWeb;
139 
140 	// delete the logging thread only after the looper thread has quit, otherwise there's
141 	// a potential race condition with the looper thread trying to write to the now-
142 	// deleted log
143 	delete mLogger;
144 }
145 
146 //
147 // Log message filtering control
148 //
149 
150 void
SetEnabled(log_what what,bool enable)151 LoggingConsumer::SetEnabled(log_what what, bool enable)
152 {
153 	mLogger->SetEnabled(what, enable);
154 }
155 
156 void
EnableAllMessages()157 LoggingConsumer::EnableAllMessages()
158 {
159 	mLogger->EnableAllMessages();
160 }
161 
162 void
DisableAllMessages()163 LoggingConsumer::DisableAllMessages()
164 {
165 	mLogger->DisableAllMessages();
166 }
167 
168 //
169 // BMediaNode methods
170 //
171 
172 
173 BMediaAddOn*
AddOn(int32 * internal_id) const174 LoggingConsumer::AddOn(int32 *internal_id) const
175 {
176 	PRINT(("~LoggingConsumer::AddOn()\n"));
177 	// e.moon [11jun99]
178 	if(m_pAddOn) {
179 		*internal_id = 0;
180 		return m_pAddOn;
181 	} else
182 		return NULL;
183 }
184 
185 void
SetRunMode(run_mode mode)186 LoggingConsumer::SetRunMode(run_mode mode)
187 {
188 	// !!! Need to handle offline mode etc. properly!
189 	log_message logMsg;
190 	logMsg.now = TimeSource()->Now();
191 	mLogger->Log(LOG_SET_RUN_MODE, logMsg);
192 
193 	BMediaEventLooper::SetRunMode(mode);
194 }
195 
196 void
Preroll()197 LoggingConsumer::Preroll()
198 {
199 	log_message logMsg;
200 	logMsg.now = TimeSource()->Now();
201 	mLogger->Log(LOG_PREROLL, logMsg);
202 
203 	BMediaEventLooper::Preroll();
204 }
205 
206 void
SetTimeSource(BTimeSource * time_source)207 LoggingConsumer::SetTimeSource(BTimeSource* time_source)
208 {
209 	log_message logMsg;
210 	logMsg.now = TimeSource()->Now();
211 	mLogger->Log(LOG_SET_TIME_SOURCE, logMsg);
212 
213 	BMediaNode::SetTimeSource(time_source);
214 }
215 
216 status_t
RequestCompleted(const media_request_info & info)217 LoggingConsumer::RequestCompleted(const media_request_info &info)
218 {
219 	log_message logMsg;
220 	logMsg.now = TimeSource()->Now();
221 	mLogger->Log(LOG_REQUEST_COMPLETED, logMsg);
222 
223 	return BMediaNode::RequestCompleted(info);
224 }
225 
226 // e.moon [11jun99; testing add-on]
227 status_t
DeleteHook(BMediaNode * pNode)228 LoggingConsumer::DeleteHook(BMediaNode* pNode) {
229 	PRINT(("LoggingConsumer::DeleteHook(%p)\n", pNode));
230 	return BBufferConsumer::DeleteHook(pNode);
231 //	ASSERT(pNode == this);
232 //	delete this;
233 //	return B_OK;
234 }
235 
236 //
237 // BControllable methods
238 //
239 
240 status_t
GetParameterValue(int32 id,bigtime_t * last_change,void * value,size_t * ioSize)241 LoggingConsumer::GetParameterValue(int32 id, bigtime_t* last_change, void* value, size_t* ioSize)
242 {
243 	log_message logMsg;
244 	logMsg.now = TimeSource()->Now();
245 	logMsg.param.id = id;
246 	mLogger->Log(LOG_GET_PARAM_VALUE, logMsg);
247 
248 	// return an error if the caller hasn't reserved enough space for the parameter data.
249 	// we know that all of our parameters fit in a float or int32 (4 bytes), so we can just
250 	// check for it once here, instead of on a per-parameter basis
251 	if (*ioSize < sizeof(float)) return B_ERROR;
252 
253 	// write out the designated parameter data
254 	switch (id)
255 	{
256 	case LATENCY_PARAM:
257 		*last_change = mLastLatencyChange;
258 		*((float*) value) = mLatency / 1000;		// the BParameter reads milliseconds, not microseconds
259 		*ioSize = sizeof(float);
260 		break;
261 
262 	case CPU_SPIN_PARAM:
263 		*last_change = mLastSpinChange;
264 		*((float*) value) = mSpinPercentage;
265 		*ioSize = sizeof(float);
266 		break;
267 
268 	case PRIORITY_PARAM:
269 		*last_change = mLastPrioChange;
270 		*((int32*) value) = mPriority;
271 		*ioSize = sizeof(int32);
272 		break;
273 
274 	default:
275 		return B_ERROR;
276 	}
277 
278 	return B_OK;
279 }
280 
281 void
SetParameterValue(int32 id,bigtime_t performance_time,const void * value,size_t size)282 LoggingConsumer::SetParameterValue(int32 id, bigtime_t performance_time, const void* value, size_t size)
283 {
284 	log_message logMsg;
285 	logMsg.now = TimeSource()->Now();
286 	logMsg.param.id = id;
287 	mLogger->Log(LOG_SET_PARAM_VALUE, logMsg);
288 
289 	// if it's one of our parameters, enqueue a "set parameter" event for handling at the appropriate time
290 	switch (id)
291 	{
292 	case LATENCY_PARAM:
293 	case CPU_SPIN_PARAM:
294 	case PRIORITY_PARAM:
295 		{
296 			// !!! Change from B_USER_EVENT to B_SET_PARAMETER once it's defined
297 			media_timed_event event(performance_time, BTimedEventQueue::B_USER_EVENT,
298 				(void*) value, BTimedEventQueue::B_NO_CLEANUP, size, id, NULL);
299 			EventQueue()->AddEvent(event);
300 		}
301 		break;
302 
303 	default:		// do nothing for other parameter IDs
304 		break;
305 	}
306 	return;
307 }
308 
309 //
310 // BBufferConsumer methods
311 //
312 
313 status_t
HandleMessage(int32 message,const void * data,size_t size)314 LoggingConsumer::HandleMessage(int32 message, const void *data, size_t size)
315 {
316 	log_message logMsg;
317 	logMsg.now = TimeSource()->Now();
318 	mLogger->Log(LOG_HANDLE_MESSAGE, logMsg);
319 
320 	// try each of our superclasses to handle the message
321 	status_t err;
322 	err = BControllable::HandleMessage(message, data, size);
323 	if (err) err = BBufferConsumer::HandleMessage(message, data, size);
324 	if (err) err = BMediaNode::HandleMessage(message, data, size);
325 	return err;
326 }
327 
328 // all of these next methods are pure virtual in BBufferConsumer
329 
330 status_t
AcceptFormat(const media_destination & dest,media_format * format)331 LoggingConsumer::AcceptFormat(const media_destination& dest, media_format* format)
332 {
333 	char formatStr[256];
334 	string_for_format(*format, formatStr, 255);
335 	PRINT(("LoggingConsumer::AcceptFormat:\n\tformat %s\n", formatStr));
336 
337 	log_message logMsg;
338 	logMsg.now = TimeSource()->Now();
339 	mLogger->Log(LOG_ACCEPT_FORMAT, logMsg);
340 
341 	// return an error if this isn't really our one input's destination
342 	if (dest != mInput.destination) return B_MEDIA_BAD_DESTINATION;
343 
344 	// the destination given really is our input, and we accept any kind of media data,
345 	// so now we just confirm that we can handle whatever the producer asked for.
346 	return B_OK;
347 }
348 
349 status_t
GetNextInput(int32 * cookie,media_input * out_input)350 LoggingConsumer::GetNextInput(int32* cookie, media_input* out_input)
351 {
352 	// we have a single hardcoded input that can accept any kind of media data
353 	if (0 == *cookie)
354 	{
355 		mInput.format.type = B_MEDIA_UNKNOWN_TYPE;		// accept any format
356 
357 		*out_input = mInput;
358 		*cookie = 1;
359 		return B_OK;
360 	}
361 	else return B_BAD_INDEX;
362 }
363 
364 void
DisposeInputCookie(int32)365 LoggingConsumer::DisposeInputCookie(int32 /*cookie*/ )
366 {
367 	// we don't use any kind of state or extra storage for iterating over our
368 	// inputs, so we don't have to do any special disposal of input cookies.
369 }
370 
371 void
BufferReceived(BBuffer * buffer)372 LoggingConsumer::BufferReceived(BBuffer* buffer)
373 {
374 	bigtime_t bufferStart = buffer->Header()->start_time;
375 	bigtime_t now = TimeSource()->Now();
376 	bigtime_t how_early = bufferStart - EventLatency() - SchedulingLatency() - now;
377 
378 	log_message logMsg;
379 	logMsg.now = now;
380 	logMsg.buffer_data.start_time = bufferStart;
381 	logMsg.buffer_data.offset = how_early;
382 	mLogger->Log(LOG_BUFFER_RECEIVED, logMsg);
383 
384 	// There's a special case here with handling B_MEDIA_PARAMETERS buffers.
385 	// These contain sets of parameter value changes, with their own performance
386 	// times embedded in the buffers.  So, we want to dispatch those parameter
387 	// changes as their own events rather than pushing this buffer on the queue to
388 	// be handled later.
389 	if (B_MEDIA_PARAMETERS == buffer->Header()->type)
390 	{
391 		ApplyParameterData(buffer->Data(), buffer->SizeUsed());
392 		buffer->Recycle();
393 	}
394 	else		// ahh, it's a regular media buffer, so push it on the event queue
395 	{
396 		status_t err;
397 		media_timed_event event(buffer->Header()->start_time, BTimedEventQueue::B_HANDLE_BUFFER,
398 			buffer, BTimedEventQueue::B_RECYCLE_BUFFER);
399 		err = EventQueue()->AddEvent(event);
400 
401 		// HandleEvent() will recycle the buffer.  However, if we incurred an error trying to
402 		// put the event into the queue, we have to recycle it ourselves, since HandleEvent()
403 		// will never see the buffer in that case.
404 		if (err) buffer->Recycle();
405 	}
406 }
407 
408 void
ProducerDataStatus(const media_destination & for_whom,int32 status,bigtime_t at_performance_time)409 LoggingConsumer::ProducerDataStatus(const media_destination& for_whom, int32 status, bigtime_t at_performance_time)
410 {
411 	log_message logMsg;
412 	logMsg.now = TimeSource()->Now();
413 	logMsg.data_status.status = status;
414 	mLogger->Log(LOG_PRODUCER_DATA_STATUS, logMsg);
415 
416 	if (for_whom == mInput.destination)
417 	{
418 		media_timed_event event(at_performance_time, BTimedEventQueue::B_DATA_STATUS,
419 			&mInput, BTimedEventQueue::B_NO_CLEANUP, status, 0, NULL);
420 		EventQueue()->AddEvent(event);
421 	}
422 }
423 
424 status_t
GetLatencyFor(const media_destination & for_whom,bigtime_t * out_latency,media_node_id * out_timesource)425 LoggingConsumer::GetLatencyFor(const media_destination& for_whom, bigtime_t* out_latency, media_node_id* out_timesource)
426 {
427 	// make sure this is one of my valid inputs
428 	if (for_whom != mInput.destination) return B_MEDIA_BAD_DESTINATION;
429 
430 	// report internal latency + downstream latency here, NOT including scheduling latency.
431 	// we're a final consumer (no outputs), so we have no downstream latency.
432 	*out_latency = mLatency;
433 	*out_timesource = TimeSource()->ID();
434 	return B_OK;
435 }
436 
437 status_t
Connected(const media_source & producer,const media_destination & where,const media_format & with_format,media_input * out_input)438 LoggingConsumer::Connected(
439 	const media_source& producer,
440 	const media_destination& where,
441 	const media_format& with_format,
442 	media_input* out_input)
443 {
444 
445 	char formatStr[256];
446 	string_for_format(with_format, formatStr, 255);
447 	PRINT(("LoggingConsumer::Connected:\n\tformat %s\n", formatStr));
448 	string_for_format(mInput.format, formatStr, 255);
449 	PRINT(("\tinput format %s\n", formatStr));
450 
451 	log_message logMsg;
452 	logMsg.now = TimeSource()->Now();
453 	mLogger->Log(LOG_CONNECTED, logMsg);
454 
455 	if (where != mInput.destination) return B_MEDIA_BAD_DESTINATION;
456 
457 	// calculate my latency here, because it may depend on buffer sizes/durations, then
458 	// tell the BMediaEventLooper how early we need to get the buffers
459 	SetEventLatency(mLatency);
460 
461 	// record useful information about the connection, and return success
462 	// * e.moon [14jun99]: stores format
463 	mInput.format = with_format;
464 	mInput.source = producer;
465 	*out_input = mInput;
466 	return B_OK;
467 }
468 
469 void
Disconnected(const media_source & producer,const media_destination & where)470 LoggingConsumer::Disconnected(
471 	const media_source& producer,
472 	const media_destination& where)
473 {
474 	log_message logMsg;
475 	logMsg.now = TimeSource()->Now();
476 	mLogger->Log(LOG_DISCONNECTED, logMsg);
477 
478 	// wipe out our input record
479 	mInput = media_input();
480 }
481 
482 status_t
FormatChanged(const media_source & producer,const media_destination & consumer,int32 change_tag,const media_format & format)483 LoggingConsumer::FormatChanged(
484 	const media_source& producer,
485 	const media_destination& consumer,
486 	int32 change_tag,
487 	const media_format& format)
488 {
489 	log_message logMsg;
490 	logMsg.now = TimeSource()->Now();
491 	mLogger->Log(LOG_FORMAT_CHANGED, logMsg);
492 
493 	return B_OK;
494 }
495 
496 status_t
SeekTagRequested(const media_destination & destination,bigtime_t in_target_time,uint32 in_flags,media_seek_tag * out_seek_tag,bigtime_t * out_tagged_time,uint32 * out_flags)497 LoggingConsumer::SeekTagRequested(
498 	const media_destination& destination,
499 	bigtime_t in_target_time,
500 	uint32 in_flags,
501 	media_seek_tag* out_seek_tag,
502 	bigtime_t* out_tagged_time,
503 	uint32* out_flags)
504 {
505 	log_message logMsg;
506 	logMsg.now = TimeSource()->Now();
507 	mLogger->Log(LOG_SEEK_TAG, logMsg);
508 
509 	return B_OK;
510 }
511 
512 //
513 // BMediaEventLooper virtual methods
514 //
515 
516 void
NodeRegistered()517 LoggingConsumer::NodeRegistered()
518 {
519 	log_message logMsg;
520 	logMsg.now = TimeSource()->Now();
521 	mLogger->Log(LOG_REGISTERED, logMsg);
522 
523 	// publish our parameter web
524 	mWeb = build_parameter_web();
525 	SetParameterWeb(mWeb);
526 
527 	// Set our priority and start the BMediaEventLooper's thread
528 	SetPriority(mPriority);
529 	Run();
530 
531 	// Initialize as much of our input as we can, now that the Media Kit really "knows" about us
532 	mInput.destination.port = ControlPort();
533 	mInput.destination.id = 0;
534 	mInput.node = Node();
535 	strcpy(mInput.name, B_TRANSLATE("Logged input"));
536 }
537 
538 void
Start(bigtime_t performance_time)539 LoggingConsumer::Start(bigtime_t performance_time)
540 {
541 	PRINT(("LoggingConsumer::Start(%" B_PRIdBIGTIME "): now %" B_PRIdBIGTIME "\n",
542 		performance_time, TimeSource()->Now()));
543 
544 	log_message logMsg;
545 	logMsg.now = TimeSource()->Now();
546 	mLogger->Log(LOG_START, logMsg);
547 
548 	BMediaEventLooper::Start(performance_time);
549 }
550 
551 void
Stop(bigtime_t performance_time,bool immediate)552 LoggingConsumer::Stop(bigtime_t performance_time, bool immediate)
553 {
554 	log_message logMsg;
555 	logMsg.now = TimeSource()->Now();
556 	mLogger->Log(LOG_STOP, logMsg);
557 
558 	BMediaEventLooper::Stop(performance_time, immediate);
559 }
560 
561 void
Seek(bigtime_t media_time,bigtime_t performance_time)562 LoggingConsumer::Seek(bigtime_t media_time, bigtime_t performance_time)
563 {
564 	log_message logMsg;
565 	logMsg.now = TimeSource()->Now();
566 	mLogger->Log(LOG_SEEK, logMsg);
567 
568 	BMediaEventLooper::Seek(media_time, performance_time);
569 }
570 
571 void
TimeWarp(bigtime_t at_real_time,bigtime_t to_performance_time)572 LoggingConsumer::TimeWarp(bigtime_t at_real_time, bigtime_t to_performance_time)
573 {
574 	log_message logMsg;
575 	logMsg.now = TimeSource()->Now();
576 	mLogger->Log(LOG_TIMEWARP, logMsg);
577 
578 	BMediaEventLooper::TimeWarp(at_real_time, to_performance_time);
579 }
580 
581 void
HandleEvent(const media_timed_event * event,bigtime_t,bool)582 LoggingConsumer::HandleEvent(const media_timed_event *event, bigtime_t /* lateness */, bool /* realTimeEvent */)
583 {
584 	log_message logMsg;
585 	logMsg.now = TimeSource()->Now();
586 	mLogger->Log(LOG_HANDLE_EVENT, logMsg);
587 
588 	switch (event->type)
589 	{
590 	case BTimedEventQueue::B_HANDLE_BUFFER:
591 		{
592 			BBuffer* buffer = const_cast<BBuffer*>((BBuffer*) event->pointer);
593 			if (buffer)
594 			{
595 				media_header* hdr = buffer->Header();
596 				if (hdr->destination == mInput.destination.id)
597 				{
598 					bigtime_t now = TimeSource()->Now();
599 					bigtime_t perf_time = hdr->start_time;
600 
601 					// the how_early calculated here doesn't include scheduling latency because
602 					// we've already been scheduled to handle the buffer
603 					bigtime_t how_early = perf_time - mLatency - now;
604 
605 					// logMsg.now is already set
606 					logMsg.buffer_data.start_time = perf_time;
607 					logMsg.buffer_data.offset = how_early;
608 					mLogger->Log(LOG_BUFFER_HANDLED, logMsg);
609 
610 					// if the buffer is late, we ignore it and report the fact to the producer
611 					// who sent it to us
612 					if (how_early < 0)
613 					{
614 						mLateBuffers++;
615 						NotifyLateProducer(mInput.source, -how_early, perf_time);
616 					}
617 					else
618 					{
619 						// burn some percentage of our stated latency in CPU time (controlled by
620 						// a BParameter).  this simulates a user-configurable amount of CPU cost
621 						// associated with the consumer.
622 						bigtime_t spin_start = ::system_time();
623 						bigtime_t spin_now = spin_start;
624 						bigtime_t usecToSpin = bigtime_t(mSpinPercentage / 100.0 * mLatency);
625 						while (spin_now - spin_start < usecToSpin)
626 						{
627 							for (long k = 0; k < 1000000; k++) { /* intentionally blank */ }
628 							spin_now = ::system_time();
629 						}
630 					}
631 
632 					// we're done "processing the buffer;" now we recycle it and return to the loop
633 					buffer->Recycle();
634 				}
635 				else
636 				{
637 					//fprintf(stderr, "* Woah!  Got a buffer for a different destination!\n");
638 				}
639 			}
640 		}
641 		break;
642 
643 	// !!! change to B_PARAMETER as soon as it's available
644 
645 	// +++++ e.moon [16jun99]
646 	// !!! this can't be right: the parameter value is accessed by the pointer
647 	//     originally passed to SetParameterValue().  there's no guarantee that
648 	//     value's still valid, is there?
649 
650 	case BTimedEventQueue::B_USER_EVENT:
651 		{
652 			size_t dataSize = size_t(event->data);
653 			int32 param = int32(event->bigdata);
654 			logMsg.param.id = param;
655 
656 			// handle the message if there's sufficient data provided.  we only check against
657 			// sizeof(float) because all of our parameters happen to be 4 bytes.  if various
658 			// parameters took different amounts of data, we'd check the size on a per-parameter
659 			// basis.
660 			if (dataSize >= sizeof(float)) switch (param)
661 			{
662 			case LATENCY_PARAM:
663 				{
664 					float value = *((float*) event->pointer);
665 					mLatency = bigtime_t(value* 1000);
666 					mLastLatencyChange = logMsg.now;
667 
668 					// my latency just changed, so reconfigure the BMediaEventLooper
669 					// to give me my events at the proper time
670 					SetEventLatency(mLatency);
671 
672 					// tell the producer that my latency changed, and broadcast a message
673 					// about the parameter change to any applications that may be looking
674 					// for it through the BMediaRoster::StartWatching() mechanism.
675 					//
676 					// if we had more than one input, we'd need to tell *all* producers about
677 					// the change in our latency.
678 					SendLatencyChange(mInput.source, mInput.destination, EventLatency() + SchedulingLatency());
679 					BroadcastNewParameterValue(logMsg.now, param, &value, sizeof(value));
680 
681 					// log the new latency value, for recordkeeping
682 					logMsg.param.value = value;
683 					mLogger->Log(LOG_SET_PARAM_HANDLED, logMsg);
684 				}
685 				break;
686 
687 			case CPU_SPIN_PARAM:
688 				{
689 					float value = *((float*) event->pointer);
690 					mSpinPercentage = value;
691 					mLastSpinChange = logMsg.now;
692 					BroadcastNewParameterValue(logMsg.now, param, &value, sizeof(value));
693 					logMsg.param.value = value;
694 					mLogger->Log(LOG_SET_PARAM_HANDLED, logMsg);
695 				}
696 				break;
697 
698 			case PRIORITY_PARAM:
699 				{
700 					mPriority = *((int32*) event->pointer);
701 					// DO NOT use ::set_thead_priority() to directly alter the node's control
702 					// thread priority.  BMediaEventLooper tracks the priority itself and recalculates
703 					// the node's scheduling latency whenever SetPriority() is called.  This is VERY
704 					// important for correct functioning of a node chain.  You should *only* alter a
705 					// BMediaEventLooper's priority by calling its SetPriority() method.
706 					SetPriority(mPriority);
707 
708 					mLastPrioChange = logMsg.now;
709 					BroadcastNewParameterValue(logMsg.now, param, &mPriority, sizeof(mPriority));
710 					logMsg.param.value = (float) mPriority;
711 					mLogger->Log(LOG_SET_PARAM_HANDLED, logMsg);
712 				}
713 				break;
714 
715 			// log the fact that we "handled" a "set parameter" event for a
716 			// nonexistent parameter
717 			default:
718 				mLogger->Log(LOG_INVALID_PARAM_HANDLED, logMsg);
719 				break;
720 			}
721 		}
722 		break;
723 
724 	case BTimedEventQueue::B_START:
725 		// okay, let's go!
726 		mLogger->Log(LOG_START_HANDLED, logMsg);
727 		break;
728 
729 	case BTimedEventQueue::B_STOP:
730 		mLogger->Log(LOG_STOP_HANDLED, logMsg);
731 		// stopping implies not handling any more buffers.  So, we flush all pending
732 		// buffers out of the event queue before returning to the event loop.
733 		EventQueue()->FlushEvents(0, BTimedEventQueue::B_ALWAYS, true, BTimedEventQueue::B_HANDLE_BUFFER);
734 		break;
735 
736 	case BTimedEventQueue::B_SEEK:
737 		// seeking the log doesn't make any sense, so we just log that we handled the seek
738 		// and return without doing anything else
739 		mLogger->Log(LOG_SEEK_HANDLED, logMsg);
740 		break;
741 
742 	case BTimedEventQueue::B_WARP:
743 		// similarly, time warps aren't meaningful to the logger, so just record it and return
744 		mLogger->Log(LOG_WARP_HANDLED, logMsg);
745 		break;
746 
747 	case BTimedEventQueue::B_DATA_STATUS:
748 		// we really don't care about the producer's data status, but this is where
749 		// we'd do something about it if we did.
750 		logMsg.data_status.status = event->data;
751 		mLogger->Log(LOG_DATA_STATUS_HANDLED, logMsg);
752 		break;
753 
754 	default:
755 		// hmm, someone enqueued a message that we don't understand.  log and ignore it.
756 		logMsg.unknown.what = event->type;
757 		mLogger->Log(LOG_HANDLE_UNKNOWN, logMsg);
758 		break;
759 	}
760 }
761