2 * Copyright 1991-1999, Be Incorporated.
3 * Copyright (c) 1999-2000, Eric Moon.
6 * Redistribution and use in source and binary forms, with or without
7 * modification, are permitted provided that the following conditions
10 * 1. Redistributions of source code must retain the above copyright
11 * notice, this list of conditions, and the following disclaimer.
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.
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.
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.
33 // LoggingConsumer.cpp
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>
48 // id's of the node's BParameters
49 const int32 INPUT_NULL_PARAM
= 1;
50 const int32 LATENCY_PARAM
= 2;
51 const int32 OUTPUT_NULL_PARAM
= 3;
52 const int32 CPU_NULL_PARAM
= 11;
53 const int32 CPU_SPIN_PARAM
= 12;
54 const int32 PRIO_NULL_PARAM
= 21;
55 const int32 PRIORITY_PARAM
= 22;
57 // build the LoggingConsumer's BParameterWeb
58 static BParameterWeb
* build_parameter_web()
60 BParameterWeb
* web
= new BParameterWeb
;
62 BParameterGroup
* mainGroup
= web
->MakeGroup("LoggingConsumer Parameters");
63 BParameterGroup
* group
= mainGroup
->MakeGroup("Latency control");
64 BParameter
* nullParam
= group
->MakeNullParameter(INPUT_NULL_PARAM
, B_MEDIA_NO_TYPE
, "Latency", B_GENERIC
);
65 BParameter
* latencyParam
= group
->MakeContinuousParameter(LATENCY_PARAM
, B_MEDIA_NO_TYPE
, "",
66 B_GAIN
, "ms", 5, 100, 5);
67 nullParam
->AddOutput(latencyParam
);
68 latencyParam
->AddInput(nullParam
);
70 group
= mainGroup
->MakeGroup("CPU percentage");
71 nullParam
= group
->MakeNullParameter(CPU_NULL_PARAM
, B_MEDIA_NO_TYPE
, "CPU spin percentage", B_GENERIC
);
72 BContinuousParameter
* cpuParam
= group
->MakeContinuousParameter(CPU_SPIN_PARAM
, B_MEDIA_NO_TYPE
, "",
73 B_GAIN
, "percent", 5, 80, 5);
74 nullParam
->AddOutput(cpuParam
);
75 cpuParam
->AddInput(nullParam
);
77 group
= mainGroup
->MakeGroup("Priority");
78 nullParam
= group
->MakeNullParameter(PRIO_NULL_PARAM
, B_MEDIA_NO_TYPE
, "Thread priority", B_GENERIC
);
79 BDiscreteParameter
* prioParam
= group
->MakeDiscreteParameter(PRIORITY_PARAM
, B_MEDIA_NO_TYPE
, "", B_GENERIC
);
80 prioParam
->AddItem(5, "B_LOW_PRIORITY");
81 prioParam
->AddItem(10, "B_NORMAL_PRIORITY");
82 prioParam
->AddItem(15, "B_DISPLAY_PRIORITY");
83 prioParam
->AddItem(20, "B_URGENT_DISPLAY_PRIORITY");
84 prioParam
->AddItem(100, "B_REAL_TIME_DISPLAY_PRIORITY");
85 prioParam
->AddItem(110, "B_URGENT_PRIORITY");
86 prioParam
->AddItem(120, "B_REAL_TIME_PRIORITY");
91 // --------------------
92 // LoggingConsumer class implementation
93 LoggingConsumer::LoggingConsumer(
94 const entry_ref
& logFile
,
97 : BMediaNode("LoggingConsumer"),
98 BBufferConsumer(B_MEDIA_UNKNOWN_TYPE
),
104 mLatency(50 * 1000), // default to 50 milliseconds
105 mSpinPercentage(0.10), // default to spinning 10% of total latency
106 mPriority(B_URGENT_DISPLAY_PRIORITY
), // !!! testing; will be B_REAL_TIME_PRIORITY for release
107 mLastLatencyChange(0),
112 // spin off the logging thread
113 mLogger
= new LogWriter(logFile
);
115 // parameter-web init moved to NodeRegistered()
119 LoggingConsumer::~LoggingConsumer()
121 PRINT(("~LoggingConsumer()\n"));
122 BMediaEventLooper::Quit();
124 // "Once you've called BControllable::SetParameterWeb(), the node takes
125 // responsibility for the parameter web object and you shouldn't delete it. "
126 // SetParameterWeb(NULL);
129 // delete the logging thread only after the looper thread has quit, otherwise there's
130 // a potential race condition with the looper thread trying to write to the now-
136 // Log message filtering control
140 LoggingConsumer::SetEnabled(log_what what
, bool enable
)
142 mLogger
->SetEnabled(what
, enable
);
146 LoggingConsumer::EnableAllMessages()
148 mLogger
->EnableAllMessages();
152 LoggingConsumer::DisableAllMessages()
154 mLogger
->DisableAllMessages();
158 // BMediaNode methods
163 LoggingConsumer::AddOn(int32
*internal_id
) const
165 PRINT(("~LoggingConsumer::AddOn()\n"));
175 LoggingConsumer::SetRunMode(run_mode mode
)
177 // !!! Need to handle offline mode etc. properly!
179 logMsg
.now
= TimeSource()->Now();
180 mLogger
->Log(LOG_SET_RUN_MODE
, logMsg
);
182 BMediaEventLooper::SetRunMode(mode
);
186 LoggingConsumer::Preroll()
189 logMsg
.now
= TimeSource()->Now();
190 mLogger
->Log(LOG_PREROLL
, logMsg
);
192 BMediaEventLooper::Preroll();
196 LoggingConsumer::SetTimeSource(BTimeSource
* time_source
)
199 logMsg
.now
= TimeSource()->Now();
200 mLogger
->Log(LOG_SET_TIME_SOURCE
, logMsg
);
202 BMediaNode::SetTimeSource(time_source
);
206 LoggingConsumer::RequestCompleted(const media_request_info
&info
)
209 logMsg
.now
= TimeSource()->Now();
210 mLogger
->Log(LOG_REQUEST_COMPLETED
, logMsg
);
212 return BMediaNode::RequestCompleted(info
);
215 // e.moon [11jun99; testing add-on]
217 LoggingConsumer::DeleteHook(BMediaNode
* pNode
) {
218 PRINT(("LoggingConsumer::DeleteHook(%p)\n", pNode
));
219 return BBufferConsumer::DeleteHook(pNode
);
220 // ASSERT(pNode == this);
226 // BControllable methods
230 LoggingConsumer::GetParameterValue(int32 id
, bigtime_t
* last_change
, void* value
, size_t* ioSize
)
233 logMsg
.now
= TimeSource()->Now();
234 logMsg
.param
.id
= id
;
235 mLogger
->Log(LOG_GET_PARAM_VALUE
, logMsg
);
237 // return an error if the caller hasn't reserved enough space for the parameter data.
238 // we know that all of our parameters fit in a float or int32 (4 bytes), so we can just
239 // check for it once here, instead of on a per-parameter basis
240 if (*ioSize
< sizeof(float)) return B_ERROR
;
242 // write out the designated parameter data
246 *last_change
= mLastLatencyChange
;
247 *((float*) value
) = mLatency
/ 1000; // the BParameter reads milliseconds, not microseconds
248 *ioSize
= sizeof(float);
252 *last_change
= mLastSpinChange
;
253 *((float*) value
) = mSpinPercentage
;
254 *ioSize
= sizeof(float);
258 *last_change
= mLastPrioChange
;
259 *((int32
*) value
) = mPriority
;
260 *ioSize
= sizeof(int32
);
271 LoggingConsumer::SetParameterValue(int32 id
, bigtime_t performance_time
, const void* value
, size_t size
)
274 logMsg
.now
= TimeSource()->Now();
275 logMsg
.param
.id
= id
;
276 mLogger
->Log(LOG_SET_PARAM_VALUE
, logMsg
);
278 // if it's one of our parameters, enqueue a "set parameter" event for handling at the appropriate time
285 // !!! Change from B_USER_EVENT to B_SET_PARAMETER once it's defined
286 media_timed_event
event(performance_time
, BTimedEventQueue::B_USER_EVENT
,
287 (void*) value
, BTimedEventQueue::B_NO_CLEANUP
, size
, id
, NULL
);
288 EventQueue()->AddEvent(event
);
292 default: // do nothing for other parameter IDs
299 // BBufferConsumer methods
303 LoggingConsumer::HandleMessage(int32 message
, const void *data
, size_t size
)
306 logMsg
.now
= TimeSource()->Now();
307 mLogger
->Log(LOG_HANDLE_MESSAGE
, logMsg
);
309 // try each of our superclasses to handle the message
311 err
= BControllable::HandleMessage(message
, data
, size
);
312 if (err
) err
= BBufferConsumer::HandleMessage(message
, data
, size
);
313 if (err
) err
= BMediaNode::HandleMessage(message
, data
, size
);
317 // all of these next methods are pure virtual in BBufferConsumer
320 LoggingConsumer::AcceptFormat(const media_destination
& dest
, media_format
* format
)
323 string_for_format(*format
, formatStr
, 255);
324 PRINT(("LoggingConsumer::AcceptFormat:\n\tformat %s\n", formatStr
));
327 logMsg
.now
= TimeSource()->Now();
328 mLogger
->Log(LOG_ACCEPT_FORMAT
, logMsg
);
330 // return an error if this isn't really our one input's destination
331 if (dest
!= mInput
.destination
) return B_MEDIA_BAD_DESTINATION
;
333 // the destination given really is our input, and we accept any kind of media data,
334 // so now we just confirm that we can handle whatever the producer asked for.
339 LoggingConsumer::GetNextInput(int32
* cookie
, media_input
* out_input
)
341 // we have a single hardcoded input that can accept any kind of media data
344 mInput
.format
.type
= B_MEDIA_UNKNOWN_TYPE
; // accept any format
350 else return B_BAD_INDEX
;
354 LoggingConsumer::DisposeInputCookie(int32
/*cookie*/ )
356 // we don't use any kind of state or extra storage for iterating over our
357 // inputs, so we don't have to do any special disposal of input cookies.
361 LoggingConsumer::BufferReceived(BBuffer
* buffer
)
363 bigtime_t bufferStart
= buffer
->Header()->start_time
;
364 bigtime_t now
= TimeSource()->Now();
365 bigtime_t how_early
= bufferStart
- EventLatency() - SchedulingLatency() - now
;
369 logMsg
.buffer_data
.start_time
= bufferStart
;
370 logMsg
.buffer_data
.offset
= how_early
;
371 mLogger
->Log(LOG_BUFFER_RECEIVED
, logMsg
);
373 // There's a special case here with handling B_MEDIA_PARAMETERS buffers.
374 // These contain sets of parameter value changes, with their own performance
375 // times embedded in the buffers. So, we want to dispatch those parameter
376 // changes as their own events rather than pushing this buffer on the queue to
378 if (B_MEDIA_PARAMETERS
== buffer
->Header()->type
)
380 ApplyParameterData(buffer
->Data(), buffer
->SizeUsed());
383 else // ahh, it's a regular media buffer, so push it on the event queue
386 media_timed_event
event(buffer
->Header()->start_time
, BTimedEventQueue::B_HANDLE_BUFFER
,
387 buffer
, BTimedEventQueue::B_RECYCLE_BUFFER
);
388 err
= EventQueue()->AddEvent(event
);
390 // HandleEvent() will recycle the buffer. However, if we incurred an error trying to
391 // put the event into the queue, we have to recycle it ourselves, since HandleEvent()
392 // will never see the buffer in that case.
393 if (err
) buffer
->Recycle();
398 LoggingConsumer::ProducerDataStatus(const media_destination
& for_whom
, int32 status
, bigtime_t at_performance_time
)
401 logMsg
.now
= TimeSource()->Now();
402 logMsg
.data_status
.status
= status
;
403 mLogger
->Log(LOG_PRODUCER_DATA_STATUS
, logMsg
);
405 if (for_whom
== mInput
.destination
)
407 media_timed_event
event(at_performance_time
, BTimedEventQueue::B_DATA_STATUS
,
408 &mInput
, BTimedEventQueue::B_NO_CLEANUP
, status
, 0, NULL
);
409 EventQueue()->AddEvent(event
);
414 LoggingConsumer::GetLatencyFor(const media_destination
& for_whom
, bigtime_t
* out_latency
, media_node_id
* out_timesource
)
416 // make sure this is one of my valid inputs
417 if (for_whom
!= mInput
.destination
) return B_MEDIA_BAD_DESTINATION
;
419 // report internal latency + downstream latency here, NOT including scheduling latency.
420 // we're a final consumer (no outputs), so we have no downstream latency.
421 *out_latency
= mLatency
;
422 *out_timesource
= TimeSource()->ID();
427 LoggingConsumer::Connected(
428 const media_source
& producer
,
429 const media_destination
& where
,
430 const media_format
& with_format
,
431 media_input
* out_input
)
435 string_for_format(with_format
, formatStr
, 255);
436 PRINT(("LoggingConsumer::Connected:\n\tformat %s\n", formatStr
));
437 string_for_format(mInput
.format
, formatStr
, 255);
438 PRINT(("\tinput format %s\n", formatStr
));
441 logMsg
.now
= TimeSource()->Now();
442 mLogger
->Log(LOG_CONNECTED
, logMsg
);
444 if (where
!= mInput
.destination
) return B_MEDIA_BAD_DESTINATION
;
446 // calculate my latency here, because it may depend on buffer sizes/durations, then
447 // tell the BMediaEventLooper how early we need to get the buffers
448 SetEventLatency(mLatency
);
450 // record useful information about the connection, and return success
451 // * e.moon [14jun99]: stores format
452 mInput
.format
= with_format
;
453 mInput
.source
= producer
;
459 LoggingConsumer::Disconnected(
460 const media_source
& producer
,
461 const media_destination
& where
)
464 logMsg
.now
= TimeSource()->Now();
465 mLogger
->Log(LOG_DISCONNECTED
, logMsg
);
467 // wipe out our input record
468 memset(&mInput
, 0, sizeof(mInput
));
472 LoggingConsumer::FormatChanged(
473 const media_source
& producer
,
474 const media_destination
& consumer
,
476 const media_format
& format
)
479 logMsg
.now
= TimeSource()->Now();
480 mLogger
->Log(LOG_FORMAT_CHANGED
, logMsg
);
486 LoggingConsumer::SeekTagRequested(
487 const media_destination
& destination
,
488 bigtime_t in_target_time
,
490 media_seek_tag
* out_seek_tag
,
491 bigtime_t
* out_tagged_time
,
495 logMsg
.now
= TimeSource()->Now();
496 mLogger
->Log(LOG_SEEK_TAG
, logMsg
);
502 // BMediaEventLooper virtual methods
506 LoggingConsumer::NodeRegistered()
509 logMsg
.now
= TimeSource()->Now();
510 mLogger
->Log(LOG_REGISTERED
, logMsg
);
512 // publish our parameter web
513 mWeb
= build_parameter_web();
514 SetParameterWeb(mWeb
);
516 // Set our priority and start the BMediaEventLooper's thread
517 SetPriority(mPriority
);
520 // Initialize as much of our input as we can, now that the Media Kit really "knows" about us
521 mInput
.destination
.port
= ControlPort();
522 mInput
.destination
.id
= 0;
523 mInput
.node
= Node();
524 strcpy(mInput
.name
, "Logged input");
528 LoggingConsumer::Start(bigtime_t performance_time
)
530 PRINT(("LoggingConsumer::Start(%" B_PRIdBIGTIME
"): now %" B_PRIdBIGTIME
"\n",
531 performance_time
, TimeSource()->Now()));
534 logMsg
.now
= TimeSource()->Now();
535 mLogger
->Log(LOG_START
, logMsg
);
537 BMediaEventLooper::Start(performance_time
);
541 LoggingConsumer::Stop(bigtime_t performance_time
, bool immediate
)
544 logMsg
.now
= TimeSource()->Now();
545 mLogger
->Log(LOG_STOP
, logMsg
);
547 BMediaEventLooper::Stop(performance_time
, immediate
);
551 LoggingConsumer::Seek(bigtime_t media_time
, bigtime_t performance_time
)
554 logMsg
.now
= TimeSource()->Now();
555 mLogger
->Log(LOG_SEEK
, logMsg
);
557 BMediaEventLooper::Seek(media_time
, performance_time
);
561 LoggingConsumer::TimeWarp(bigtime_t at_real_time
, bigtime_t to_performance_time
)
564 logMsg
.now
= TimeSource()->Now();
565 mLogger
->Log(LOG_TIMEWARP
, logMsg
);
567 BMediaEventLooper::TimeWarp(at_real_time
, to_performance_time
);
571 LoggingConsumer::HandleEvent(const media_timed_event
*event
, bigtime_t
/* lateness */, bool /* realTimeEvent */)
574 logMsg
.now
= TimeSource()->Now();
575 mLogger
->Log(LOG_HANDLE_EVENT
, logMsg
);
579 case BTimedEventQueue::B_HANDLE_BUFFER
:
581 BBuffer
* buffer
= const_cast<BBuffer
*>((BBuffer
*) event
->pointer
);
584 media_header
* hdr
= buffer
->Header();
585 if (hdr
->destination
== mInput
.destination
.id
)
587 bigtime_t now
= TimeSource()->Now();
588 bigtime_t perf_time
= hdr
->start_time
;
590 // the how_early calculated here doesn't include scheduling latency because
591 // we've already been scheduled to handle the buffer
592 bigtime_t how_early
= perf_time
- mLatency
- now
;
594 // logMsg.now is already set
595 logMsg
.buffer_data
.start_time
= perf_time
;
596 logMsg
.buffer_data
.offset
= how_early
;
597 mLogger
->Log(LOG_BUFFER_HANDLED
, logMsg
);
599 // if the buffer is late, we ignore it and report the fact to the producer
604 NotifyLateProducer(mInput
.source
, -how_early
, perf_time
);
608 // burn some percentage of our stated latency in CPU time (controlled by
609 // a BParameter). this simulates a user-configurable amount of CPU cost
610 // associated with the consumer.
611 bigtime_t spin_start
= ::system_time();
612 bigtime_t spin_now
= spin_start
;
613 bigtime_t usecToSpin
= bigtime_t(mSpinPercentage
/ 100.0 * mLatency
);
614 while (spin_now
- spin_start
< usecToSpin
)
616 for (long k
= 0; k
< 1000000; k
++) { /* intentionally blank */ }
617 spin_now
= ::system_time();
621 // we're done "processing the buffer;" now we recycle it and return to the loop
626 //fprintf(stderr, "* Woah! Got a buffer for a different destination!\n");
632 // !!! change to B_PARAMETER as soon as it's available
634 // +++++ e.moon [16jun99]
635 // !!! this can't be right: the parameter value is accessed by the pointer
636 // originally passed to SetParameterValue(). there's no guarantee that
637 // value's still valid, is there?
639 case BTimedEventQueue::B_USER_EVENT
:
641 size_t dataSize
= size_t(event
->data
);
642 int32 param
= int32(event
->bigdata
);
643 logMsg
.param
.id
= param
;
645 // handle the message if there's sufficient data provided. we only check against
646 // sizeof(float) because all of our parameters happen to be 4 bytes. if various
647 // parameters took different amounts of data, we'd check the size on a per-parameter
649 if (dataSize
>= sizeof(float)) switch (param
)
653 float value
= *((float*) event
->pointer
);
654 mLatency
= bigtime_t(value
* 1000);
655 mLastLatencyChange
= logMsg
.now
;
657 // my latency just changed, so reconfigure the BMediaEventLooper
658 // to give me my events at the proper time
659 SetEventLatency(mLatency
);
661 // tell the producer that my latency changed, and broadcast a message
662 // about the parameter change to any applications that may be looking
663 // for it through the BMediaRoster::StartWatching() mechanism.
665 // if we had more than one input, we'd need to tell *all* producers about
666 // the change in our latency.
667 SendLatencyChange(mInput
.source
, mInput
.destination
, EventLatency() + SchedulingLatency());
668 BroadcastNewParameterValue(logMsg
.now
, param
, &value
, sizeof(value
));
670 // log the new latency value, for recordkeeping
671 logMsg
.param
.value
= value
;
672 mLogger
->Log(LOG_SET_PARAM_HANDLED
, logMsg
);
678 float value
= *((float*) event
->pointer
);
679 mSpinPercentage
= value
;
680 mLastSpinChange
= logMsg
.now
;
681 BroadcastNewParameterValue(logMsg
.now
, param
, &value
, sizeof(value
));
682 logMsg
.param
.value
= value
;
683 mLogger
->Log(LOG_SET_PARAM_HANDLED
, logMsg
);
689 mPriority
= *((int32
*) event
->pointer
);
690 // DO NOT use ::set_thead_priority() to directly alter the node's control
691 // thread priority. BMediaEventLooper tracks the priority itself and recalculates
692 // the node's scheduling latency whenever SetPriority() is called. This is VERY
693 // important for correct functioning of a node chain. You should *only* alter a
694 // BMediaEventLooper's priority by calling its SetPriority() method.
695 SetPriority(mPriority
);
697 mLastPrioChange
= logMsg
.now
;
698 BroadcastNewParameterValue(logMsg
.now
, param
, &mPriority
, sizeof(mPriority
));
699 logMsg
.param
.value
= (float) mPriority
;
700 mLogger
->Log(LOG_SET_PARAM_HANDLED
, logMsg
);
704 // log the fact that we "handled" a "set parameter" event for a
705 // nonexistent parameter
707 mLogger
->Log(LOG_INVALID_PARAM_HANDLED
, logMsg
);
713 case BTimedEventQueue::B_START
:
715 mLogger
->Log(LOG_START_HANDLED
, logMsg
);
718 case BTimedEventQueue::B_STOP
:
719 mLogger
->Log(LOG_STOP_HANDLED
, logMsg
);
720 // stopping implies not handling any more buffers. So, we flush all pending
721 // buffers out of the event queue before returning to the event loop.
722 EventQueue()->FlushEvents(0, BTimedEventQueue::B_ALWAYS
, true, BTimedEventQueue::B_HANDLE_BUFFER
);
725 case BTimedEventQueue::B_SEEK
:
726 // seeking the log doesn't make any sense, so we just log that we handled the seek
727 // and return without doing anything else
728 mLogger
->Log(LOG_SEEK_HANDLED
, logMsg
);
731 case BTimedEventQueue::B_WARP
:
732 // similarly, time warps aren't meaningful to the logger, so just record it and return
733 mLogger
->Log(LOG_WARP_HANDLED
, logMsg
);
736 case BTimedEventQueue::B_DATA_STATUS
:
737 // we really don't care about the producer's data status, but this is where
738 // we'd do something about it if we did.
739 logMsg
.data_status
.status
= event
->data
;
740 mLogger
->Log(LOG_DATA_STATUS_HANDLED
, logMsg
);
744 // hmm, someone enqueued a message that we don't understand. log and ignore it.
745 logMsg
.unknown
.what
= event
->type
;
746 mLogger
->Log(LOG_HANDLE_UNKNOWN
, logMsg
);