fixed (hopefully) all latency bugs

fixed BMediaRoster::MakeTimeSourceFor()


git-svn-id: file:///srv/svn/repos/haiku/trunk/current@3397 a95241bf-73f2-0310-859d-f6bbb57e9c96

headers/private/media/MediaMisc.h

@@ -34,6 +34,9 @@
 
 #define ROUND_UP_TO_PAGE(size)			(((size) + B_PAGE_SIZE - 1) & ~(B_PAGE_SIZE - 1))
 
+#define MEDIA_SERVER_PORT_NAME			"__media_server_port"
+#define MEDIA_ADDON_SERVER_PORT_NAME	"__media_addon_server_port"
+
 namespace BPrivate { namespace media {
 	extern team_id team;
 } } // BPrivate::media

src/add-ons/media/media-add-ons/mixer/AudioMixer.cpp

@@ -529,12 +529,6 @@ AudioMixer::BufferReceived(BBuffer *buffer)
 		return;
 	}
 
-	bigtime_t now = system_time(); // XXX debugging
-	bigtime_t send = buffer->Header()->file_pos; // XXX debugging
-//	printf("buffer received at %10Ld, was send at %10Ld, delta %7Ld  # ", now, send, now - send);
-
-
-//	printf("2) should arrive at %20Ld, now %20Ld\n", buffer->Header()->start_time, TimeSource()->Now());
 //	printf("buffer received at %12Ld, should arrive at %12Ld, delta %12Ld\n", TimeSource()->Now(), buffer->Header()->start_time, TimeSource()->Now() - buffer->Header()->start_time);
 
 	// to receive the buffer at the right time,
@@ -544,9 +538,6 @@ AudioMixer::BufferReceived(BBuffer *buffer)
 							buffer,
 							BTimedEventQueue::B_RECYCLE_BUFFER);
 	EventQueue()->AddEvent(event);
-	
-	uint32 dummy;
-	write_port(ControlPort(), -1, &dummy, sizeof(dummy));
 }
 
 
@@ -557,12 +548,6 @@ AudioMixer::HandleInputBuffer(BBuffer *buffer, bigtime_t lateness)
 
 //	printf("latency = %12Ld, event = %12Ld, sched = %5Ld, arrive at %12Ld, now %12Ld, current lateness %12Ld\n", EventLatency() + SchedulingLatency(), EventLatency(), SchedulingLatency(), buffer->Header()->start_time, TimeSource()->Now(), lateness);
 
-//	printf("3) should arrive at %20Ld, now %20Ld\n", buffer->Header()->start_time, TimeSource()->Now());
-
-//	bigtime_t now = TimeSource()->Now();
-//	bigtime_t perf_time = hdr->start_time;				
-//	bigtime_t how_late = now - perf_time - fLatency;
-		
 	// check input
 	int inputcount = fMixerInputs.CountItems();
 	
@@ -574,10 +559,10 @@ AudioMixer::HandleInputBuffer(BBuffer *buffer, bigtime_t lateness)
 			continue;
 
 		if (lateness > 5000) {
-			printf("Received buffer with lateness %Ld\n", lateness);
-			if (RunMode() != B_OFFLINE && RunMode() != B_RECORDING) {
-//				printf("sending notify\n");
-//				NotifyLateProducer(channel->fInput.source, lateness, TimeSource()->Now());
+			printf("Received buffer with way to high lateness %Ld\n", lateness);
+			if (RunMode() != B_DROP_DATA) {
+				printf("sending notify\n");
+				NotifyLateProducer(channel->fInput.source, lateness / 2, TimeSource()->Now());
 			} else if (RunMode() == B_DROP_DATA) {
 				printf("dropping buffer\n");
 				return;
@@ -596,6 +581,7 @@ AudioMixer::HandleInputBuffer(BBuffer *buffer, bigtime_t lateness)
 		if (channel->fDataSize == 0)
 			break;
 		
+		// XXX this is probably broken now
 		size_t total_offset = int(channel->fEventOffset + channel->fInput.format.u.raw_audio.buffer_size)  % int(channel->fDataSize);
 		
 		char *indata = (char *)buffer->Data();
@@ -620,14 +606,16 @@ AudioMixer::HandleInputBuffer(BBuffer *buffer, bigtime_t lateness)
 void
 AudioMixer::SendNewBuffer(bigtime_t event_time)
 {
+	// XXX All of this should be handled in a different thread to avoid blocking the control loop
+	
 	bigtime_t start = system_time();
-	BBuffer *outbuffer = fBufferGroup->RequestBuffer(fOutput.format.u.raw_audio.buffer_size, BufferDuration() / 4);
+	BBuffer *outbuffer = fBufferGroup->RequestBuffer(fOutput.format.u.raw_audio.buffer_size, BufferDuration() / 2);
 	bigtime_t delta = system_time() - start;
-	if (delta > 200)
-		printf("RequestBuffer took %Ld usec\n", delta);
+	if (delta > 1000)
+		printf("AudioMixer::SendNewBuffer: RequestBuffer took %Ld usec\n", delta);
 
 	if (!outbuffer) {
-		printf("AudioMixer: Could not allocate buffer\n");
+		printf("AudioMixer::SendNewBuffer: Could not allocate buffer\n");
 		return;
 	}
 				
@@ -645,8 +633,8 @@ AudioMixer::SendNewBuffer(bigtime_t event_time)
 		outbuffer->Recycle();
 	}
 	bigtime_t delta2 = system_time() - start2;
-	if (delta2 > 200)
-		printf("SendBuffer took %Ld usec\n", delta2);
+	if (delta2 > 1000)
+		printf("AudioMixer::SendNewBuffer: SendBuffer took %Ld usec\n", delta2);
 }
 
 
@@ -660,8 +648,6 @@ AudioMixer::ProducerDataStatus( const media_destination &for_whom,
 		media_timed_event event(at_performance_time, BTimedEventQueue::B_DATA_STATUS,
 			(void *)(&for_whom), BTimedEventQueue::B_NO_CLEANUP, status, 0, NULL);
 		EventQueue()->AddEvent(event);
-		uint32 dummy;
-		write_port(ControlPort(), -1, &dummy, sizeof(dummy));
 		
 		// FIX_THIS
 		// the for_whom destination is not being sent correctly - verify in HandleEvent loop
@@ -1090,7 +1076,6 @@ AudioMixer::Connect( status_t error, const media_source &source, const media_des
 	media_node_id id;
 	FindLatencyFor(fOutput.destination, &fLatency, &id);
 	printf("Downstream Latency is %Ld usecs\n", fLatency);
-	fLatency += 6000;
 
 	// we need at least the length of a full output buffer's latency (I think?)
 
@@ -1109,6 +1094,11 @@ AudioMixer::Connect( status_t error, const media_source &source, const media_des
 	fInternalLatency = latency_end - latency_start;
 	printf("Internal latency is %Ld usecs\n", fInternalLatency);
 	
+	// use a higher internal latency to be able to process buffers that arrive late
+	// XXX does this make sense?
+	if (fInternalLatency < 5000)
+		fInternalLatency = 5000;
+	
 	delete mouse;
 	
 	// might need to tweak the latency
@@ -1163,8 +1153,8 @@ AudioMixer::LateNoticeReceived(const media_source &what, bigtime_t how_much, big
 		if (RunMode() == B_INCREASE_LATENCY) {
 			fInternalLatency += how_much;
 
-//			if (fInternalLatency > 50000)
-//				fInternalLatency = 50000;
+			if (fInternalLatency > 50000)
+				fInternalLatency = 50000;
 
 			printf("AudioMixer: increasing internal latency to %Ld usec\n", fInternalLatency);
 			SetEventLatency(fLatency + fInternalLatency);
@@ -1245,7 +1235,7 @@ AudioMixer::HandleEvent( const media_timed_event *event, bigtime_t lateness, boo
 
 		case SEND_NEW_BUFFER_EVENT:
 		{
-
+			// if the output is connected and enabled, send a bufffer
 			if (fOutputEnabled && fOutput.destination != media_destination::null)
 				SendNewBuffer(event->event_time);
 			
@@ -1265,8 +1255,6 @@ AudioMixer::HandleEvent( const media_timed_event *event, bigtime_t lateness, boo
 			bigtime_t nextevent = TimeSource()->PerformanceTimeFor(bigtime_t(fStartTime + double(fFramesSent / fOutput.format.u.raw_audio.frame_rate) * 1000000.0));
 			media_timed_event nextBufferEvent(nextevent, SEND_NEW_BUFFER_EVENT);
 			EventQueue()->AddEvent(nextBufferEvent);
-			uint32 dummy;
-			write_port(ControlPort(), -1, &dummy, sizeof(dummy));
 			break;
 		}
 		
@@ -1289,8 +1277,6 @@ AudioMixer::HandleEvent( const media_timed_event *event, bigtime_t lateness, boo
 				//		this->HandleEvent(&firstBufferEvent, 0, false);
 				//
 				EventQueue()->AddEvent(firstBufferEvent);
-				uint32 dummy;
-				write_port(ControlPort(), -1, &dummy, sizeof(dummy));
 				
 				//	fStartTime = event->event_time;
 	

src/kits/media/DataExchange.cpp

@@ -52,7 +52,7 @@ initit _initit;
 
 void find_media_server_port()
 {
-	MediaServerPort = find_port("media_server port");
+	MediaServerPort = find_port(MEDIA_SERVER_PORT_NAME);
 	if (MediaServerPort < 0) {
 		FATAL("couldn't find MediaServerPort\n");
 		MediaServerPort = BAD_MEDIA_SERVER_PORT; // make this a unique number
@@ -61,7 +61,7 @@ void find_media_server_port()
 
 void find_media_addon_server_port()
 {
-	MediaAddonServerPort = find_port("media_addon_server port");
+	MediaAddonServerPort = find_port(MEDIA_ADDON_SERVER_PORT_NAME);
 	if (MediaAddonServerPort < 0) {
 		FATAL("couldn't find MediaAddonServerPort\n");
 		MediaAddonServerPort = BAD_MEDIA_ADDON_SERVER_PORT; // make this a unique number

src/kits/media/DormantNodeManager.cpp

@@ -55,6 +55,7 @@ static char __copyright[] = "Copyright (c) 2002, 2003 Marcus Overhagen <Marcus@O
 #include <MediaAddOn.h>
 #include "debug.h"
 #include "PortPool.h"
+#include "MediaMisc.h"
 #include "ServerInterface.h"
 #include "DataExchange.h"
 #include "DormantNodeManager.h"
@@ -215,7 +216,7 @@ DormantNodeManager::RegisterAddon(const char *path)
 		return 0;
 	}
 	msg.ref = tempref;
-	port = find_port("media_server port");
+	port = find_port(MEDIA_SERVER_PORT_NAME);
 	if (port <= B_OK) {
 		FATAL("DormantNodeManager::RegisterAddon failed, couldn't find media server\n");
 		return 0;
@@ -249,7 +250,7 @@ DormantNodeManager::UnregisterAddon(media_addon_id id)
 	TRACE("DormantNodeManager::UnregisterAddon id %ld\n",id);
 
 	port_id port;
-	port = find_port("media_server port");
+	port = find_port(MEDIA_SERVER_PORT_NAME);
 	if (port <= B_OK)
 		return;
 	msg.addonid = id;
@@ -266,7 +267,7 @@ DormantNodeManager::FindAddonPath(BPath *path, media_addon_id id)
 	entry_ref tempref;
 	status_t rv;
 	int32 code;
-	port = find_port("media_server port");
+	port = find_port(MEDIA_SERVER_PORT_NAME);
 	if (port <= B_OK)
 		return B_ERROR;
 	msg.addonid = id;

src/kits/media/MediaNode.cpp

@@ -209,8 +209,8 @@ BMediaNode::Node() const
 {
 	CALLED();
 	media_node temp;
-	temp.node = fNodeID;
-	temp.port = fControlPort;
+	temp.node = ID();
+	temp.port = ControlPort(); // we *must* call ControlPort(), some derived nodes use it to start the port read thread!
 	temp.kind = Kinds();
 	return temp;
 }
@@ -233,7 +233,7 @@ BMediaNode::TimeSource() const
 	if (fTimeSource != 0)
 		return fTimeSource;
 		
-	printf("BMediaNode::TimeSource node %ld enter\n", ID());
+	TRACE("BMediaNode::TimeSource node %ld enter\n", ID());
 	
 	// If the node doesn't have a time source object, we need to create one.
 	// If the node is still unregistered, we can't call MakeTimeSourceFor(),
@@ -255,7 +255,7 @@ BMediaNode::TimeSource() const
 		fTimeSource->AddMe(self);
 	}
 
-	printf("BMediaNode::TimeSource node %ld leave\n", ID());
+	TRACE("BMediaNode::TimeSource node %ld leave\n", ID());
 
 	return fTimeSource;
 }
@@ -355,18 +355,13 @@ BMediaNode::WaitForMessage(bigtime_t waitUntil,
 	int32 message;
 	ssize_t size;
 	
-	size = read_port_etc(fControlPort, &message, data, sizeof(data), B_ABSOLUTE_TIMEOUT, waitUntil);
+	size = read_port_etc(ControlPort(), &message, data, sizeof(data), B_ABSOLUTE_TIMEOUT, waitUntil);
 	if (size <= 0) {
 		if (size != B_TIMED_OUT)
 			FATAL("BMediaNode::WaitForMessage: read_port_etc error 0x%08lx\n",size);
 		return size; // returns the error code
 	}
 
-	if (message == -1) {
-		//printf("BMediaNode::WaitForMessage dummy received\n");
-		return B_OK;
-	}
-
 	TRACE("BMediaNode::WaitForMessage %#lx, node %ld, this %p\n", message, fNodeID, this);
 
 	if (message > NODE_MESSAGE_START && message < NODE_MESSAGE_END) {
@@ -595,9 +590,8 @@ BMediaNode::HandleMessage(int32 message,
 		case NODE_SET_TIMESOURCE:
 		{
 			const node_set_timesource_command *command = static_cast<const node_set_timesource_command *>(data);
-			TRACE("NODE_SET_TIMESOURCE, node %ld, timesource %ld\n", fNodeID, command->timesource_id);
 
-			printf("NODE_SET_TIMESOURCE, node %ld, timesource %ld enter\n", fNodeID, command->timesource_id);
+			TRACE("NODE_SET_TIMESOURCE, node %ld, timesource %ld enter\n", fNodeID, command->timesource_id);
 			
 			fTimeSourceID = command->timesource_id;
 			
@@ -617,7 +611,7 @@ BMediaNode::HandleMessage(int32 message,
 			// any derived class
 			SetTimeSource(fTimeSource);
 
-			printf("NODE_SET_TIMESOURCE, node %ld, timesource %ld leave\n", fNodeID, command->timesource_id);
+			TRACE("NODE_SET_TIMESOURCE, node %ld, timesource %ld leave\n", fNodeID, command->timesource_id);
 
 			return B_OK;
 		}

src/kits/media/MediaRoster.cpp

@@ -1568,6 +1568,8 @@ BMediaRosterEx::RegisterNode(BMediaNode * node, media_addon_id addonid, int32 fl
 		return rv;
 	}
 
+	TRACE("BMediaRoster::RegisterNode: QueryServer SERVER_REGISTER_NODE finished\n");
+	
 	// we are a friend class of BMediaNode and initialize this member variable
 	node->fNodeID = reply.nodeid;
 	ASSERT(reply.nodeid == node->Node().node);
@@ -1576,6 +1578,8 @@ BMediaRosterEx::RegisterNode(BMediaNode * node, media_addon_id addonid, int32 fl
 	// call the callback
 	node->NodeRegistered();
 
+	TRACE("BMediaRoster::RegisterNode: NodeRegistered callback finished\n");
+	
 	// if the BMediaNode also inherits from BTimeSource, we need to call BTimeSource::FinishCreate()
 	if (node->Kinds() & B_TIME_SOURCE) {
 		BTimeSource *ts;
@@ -1584,9 +1588,12 @@ BMediaRosterEx::RegisterNode(BMediaNode * node, media_addon_id addonid, int32 fl
 			ts->FinishCreate();
 	}
 
+	TRACE("BMediaRoster::RegisterNode: publishing inputs/outputs\n");
+
 	// register existing inputs and outputs with the
 	// media_server, this allows GetLiveNodes() to work
 	// with created, but unconnected nodes.
+
 	if (node->Kinds() & B_BUFFER_PRODUCER) {
 		List<media_output> list;
 		if (B_OK == GetAllOutputs(node->Node(), &list))
@@ -1598,7 +1605,12 @@ BMediaRosterEx::RegisterNode(BMediaNode * node, media_addon_id addonid, int32 fl
 			PublishInputs(node->Node(), &list);
 	}
 
+	TRACE("BMediaRoster::RegisterNode: sending NodesCreated\n");
+
 	BPrivate::media::notifications::NodesCreated(&reply.nodeid, 1);
+
+	TRACE("BMediaRoster::RegisterNode: finished\n");
+
 /*
 	TRACE("BMediaRoster::RegisterNode: registered node name '%s', id %ld, addon %ld, flavor %ld\n", node->Name(), node->ID(), addon_id, addon_flavor_id);
 	TRACE("BMediaRoster::RegisterNode: node this               %p\n", node);
@@ -1851,7 +1863,7 @@ BMediaRoster::GetDormantNodes(dormant_node_info * out_info,
 	port_id port;
 	status_t rv;
 
-	port = find_port("media_server port");
+	port = find_port(MEDIA_SERVER_PORT_NAME);
 	if (port <= B_OK)
 		return B_ERROR;
 	
@@ -2152,7 +2164,7 @@ BMediaRosterEx::GetDormantFlavorInfo(media_addon_id addonid,
 	status_t rv;
 	int32 code;
 
-	port = find_port("media_server port");
+	port = find_port(MEDIA_SERVER_PORT_NAME);
 	if (port <= B_OK)
 		return B_ERROR;
 

src/kits/media/SoundPlayNode.cpp

@@ -79,8 +79,7 @@ _SoundPlayNode::Format() const
 // implementation of BMediaNode
 // -------------------------------------------------------- //
 
-BMediaAddOn * _SoundPlayNode::AddOn(
-				int32 * internal_id) const
+BMediaAddOn * _SoundPlayNode::AddOn(int32 * internal_id) const
 {
 	CALLED();
 	// BeBook says this only gets called if we were in an add-on.
@@ -94,10 +93,7 @@ void _SoundPlayNode::Preroll(void)
 	BMediaNode::Preroll();
 }
 
-status_t _SoundPlayNode::HandleMessage(
-				int32 message,
-				const void * data,
-				size_t size)
+status_t _SoundPlayNode::HandleMessage(int32 message, const void * data, size_t size)
 {
 	CALLED();
 	return B_ERROR;
@@ -156,23 +152,13 @@ _SoundPlayNode::FormatSuggestionRequested(media_type type, int32 /*quality*/, me
 	// preferred data format is, given a suggestion by the caller.
 	CALLED();
 
-	if (!format)
-	{
-		fprintf(stderr, "\tERROR - NULL format pointer passed in!\n");
-		return B_BAD_VALUE;
-	}
+	// a wildcard type is okay; but we only support raw audio
+	if (type != B_MEDIA_RAW_AUDIO && type != B_MEDIA_UNKNOWN_TYPE)
+		return B_MEDIA_BAD_FORMAT;
 
 	// this is the format we'll be returning (our preferred format)
 	*format = mFormat;
 
-	// a wildcard type is okay; we can specialize it
-	if (type == B_MEDIA_UNKNOWN_TYPE)
-		type = B_MEDIA_RAW_AUDIO;
-
-	// we only support raw audio
-	if (type != B_MEDIA_RAW_AUDIO)
-		return B_MEDIA_BAD_FORMAT;
-	
 	return B_OK;
 }
 
@@ -182,9 +168,9 @@ _SoundPlayNode::FormatProposal(const media_source& output, media_format* format)
 	// FormatProposal() is the first stage in the BMediaRoster::Connect() process.  We hand
 	// out a suggested format, with wildcards for any variations we support.
 	CALLED();
+
 	// is this a proposal for our one output?
-	if (output != mOutput.source)
-	{
+	if (output != mOutput.source) {
 		fprintf(stderr, "_SoundPlayNode::FormatProposal returning B_MEDIA_BAD_SOURCE\n");
 		return B_MEDIA_BAD_SOURCE;
 	}
@@ -193,12 +179,12 @@ _SoundPlayNode::FormatProposal(const media_source& output, media_format* format)
 	// supply an error code depending on whether we found the proposal acceptable.
 	media_type requestedType = format->type;
 	*format = mFormat;
-	if ((requestedType != B_MEDIA_UNKNOWN_TYPE) && (requestedType != B_MEDIA_RAW_AUDIO))
-	{
+	if ((requestedType != B_MEDIA_UNKNOWN_TYPE) && (requestedType != B_MEDIA_RAW_AUDIO)) {
 		fprintf(stderr, "_SoundPlayNode::FormatProposal returning B_MEDIA_BAD_FORMAT\n");
 		return B_MEDIA_BAD_FORMAT;
 	}
-	else return B_OK;		// raw audio or wildcard type, either is okay by us
+	else
+		return B_OK;		// raw audio or wildcard type, either is okay by us
 }
 
 status_t 
@@ -237,8 +223,7 @@ _SoundPlayNode::SetBufferGroup(const media_source& for_source, BBufferGroup* new
 	CALLED();
 
 	// is this our output?
-	if (for_source != mOutput.source)
-	{
+	if (for_source != mOutput.source) {
 		fprintf(stderr, "_SoundPlayNode::SetBufferGroup returning B_MEDIA_BAD_SOURCE\n");
 		return B_MEDIA_BAD_SOURCE;
 	}
@@ -265,6 +250,8 @@ _SoundPlayNode::SetBufferGroup(const media_source& for_source, BBufferGroup* new
 		// our own buffer group to use from now on
 		size_t size = mOutput.format.u.raw_audio.buffer_size;
 		int32 count = int32(mLatency / BufferDuration() + 1 + 1);
+		if (count < 3)
+			count = 3;
 		mBufferGroup = new BBufferGroup(size, count);
 	}
 
@@ -372,7 +359,7 @@ _SoundPlayNode::Connect(status_t error, const media_source& source, const media_
 	FindLatencyFor(mOutput.destination, &mLatency, &id);
 	fprintf(stderr, "\tdownstream latency = %Ld\n", mLatency);
 
-	mInternalLatency = 1000LL;
+	mInternalLatency = 10000LL;
 	fprintf(stderr, "\tbuffer-filling took %Ld usec on this machine\n", mInternalLatency);
 	SetEventLatency(mLatency + mInternalLatency);
 
@@ -433,18 +420,6 @@ _SoundPlayNode::LateNoticeReceived(const media_source& what, bigtime_t how_much,
 		return;
 	}
 
-	// If we're late, we need to catch up.  Respond in a manner appropriate to our
-	// current run mode.
-/*
-	if (RunMode() == B_RECORDING)
-	{
-		// A hardware capture node can't adjust; it simply emits buffers at
-		// appropriate points.  We (partially) simulate this by not adjusting
-		// our behavior upon receiving late notices -- after all, the hardware
-		// can't choose to capture "sooner"....
-	}
-	else if (RunMode() == B_INCREASE_LATENCY)
-*/
 	if (RunMode() != B_DROP_DATA)
 	{
 		// We're late, and our run mode dictates that we try to produce buffers
@@ -453,23 +428,25 @@ _SoundPlayNode::LateNoticeReceived(const media_source& what, bigtime_t how_much,
 		// that at the moment, so we try to start producing buffers earlier to
 		// compensate.
 		
+		mInternalLatency += how_much;
 
-//		mInternalLatency += how_much;
+		if (mInternalLatency > 30000)	// avoid getting a too high latency
+			mInternalLatency = 30000;
 
-//		if (mInternalLatency > 50000)
-//			mInternalLatency = 50000;
-
-//		SetEventLatency(mLatency + mInternalLatency);
-
-//		fprintf(stderr, "\tincreasing latency to %Ld\n", mLatency + mInternalLatency);
+		SetEventLatency(mLatency + mInternalLatency);
+		fprintf(stderr, "\tincreasing latency to %Ld\n", mLatency + mInternalLatency);
 	}
 	else
 	{
 		// The other run modes dictate various strategies for sacrificing data quality
 		// in the interests of timely data delivery.  The way *we* do this is to skip
 		// a buffer, which catches us up in time by one buffer duration.
-		/*size_t nSamples = mOutput.format.u.raw_audio.buffer_size / sizeof(float);
-		mSamplesSent += nSamples;*/
+
+		size_t nFrames = mOutput.format.u.raw_audio.buffer_size
+			/ ((mOutput.format.u.raw_audio.format & media_raw_audio_format::B_AUDIO_SIZE_MASK)
+			* mOutput.format.u.raw_audio.channel_count);
+
+		mFramesSent += nFrames;
 
 		fprintf(stderr, "\tskipping a buffer to try to catch up\n");
 	}
@@ -570,16 +547,11 @@ void _SoundPlayNode::HandleEvent(
 // how should we handle late buffers?  drop them?
 // notify the producer?
 status_t 
-_SoundPlayNode::SendNewBuffer(
-				const media_timed_event *event,
-				bigtime_t lateness,
-				bool realTimeEvent)
+_SoundPlayNode::SendNewBuffer(const media_timed_event *event, bigtime_t lateness, bool realTimeEvent)
 {
 	CALLED();
 //	printf("latency = %12Ld, event = %12Ld, sched = %5Ld, arrive at %12Ld, now %12Ld, current lateness %12Ld\n", EventLatency() + SchedulingLatency(), EventLatency(), SchedulingLatency(), event->event_time, TimeSource()->Now(), lateness);
 
-//	printf("1) should arrive at %20Ld, now %20Ld\n", event->event_time, TimeSource()->Now());
-		
 	// make sure we're both started *and* connected before delivering a buffer
 	if ((RunState() != BMediaEventLooper::B_STARTED) || (mOutput.destination == media_destination::null))
 		return B_OK;
@@ -587,13 +559,10 @@ _SoundPlayNode::SendNewBuffer(
 	// The event->event_time is the time at which the buffer we are preparing here should
 	// arrive at it's destination. The MediaEventLooper should have scheduled us early enough
 	// (based on EventLatency() and the SchedulingLatency()) to make this possible.
+	// lateness is independent of EventLatency()!
 
-//	bigtime_t scheduling_latency = SchedulingLatency();
-
-	if (lateness > 5000) {
-		printf("_SoundPlayNode::SendNewBuffer, event sheduled too late, lateness is %Ld\n", lateness);
-//		mInternalLatency += 1000;
-//		SetEventLatency(mLatency + mInternalLatency);
+	if (lateness > 1000) {
+		printf("_SoundPlayNode::SendNewBuffer, event scheduled much too late, lateness is %Ld\n", lateness);
 	}
 
 	// skip buffer creation if output not enabled	
@@ -622,17 +591,12 @@ _SoundPlayNode::SendNewBuffer(
 			}
 */
 			// send the buffer downstream if and only if output is enabled
-			bigtime_t start = system_time();
-			buffer->Header()->file_pos = (off_t)start; // XXX debugging
 			if (B_OK != SendBuffer(buffer, mOutput.destination)) {
 				// we need to recycle the buffer
 				// if the call to SendBuffer() fails
 				printf("Buffer sending failed\n");
 				buffer->Recycle();
 			}
-			bigtime_t delta = system_time() - start;
-			if (delta > 200)
-				printf("SendBuffer took %Ld usec\n", delta);
 		}
 	}
 
@@ -646,10 +610,7 @@ _SoundPlayNode::SendNewBuffer(
 	// nextEvent is the time at which the buffer should arrive at it's destination
 	bigtime_t nextEvent = TimeSource()->PerformanceTimeFor(mStartTime + bigtime_t((1000000LL * mFramesSent) / mOutput.format.u.raw_audio.frame_rate));
 	media_timed_event nextBufferEvent(nextEvent, SEND_NEW_BUFFER_EVENT);
-//	printf("0) should arrive at %20Ld, now %20Ld\n", nextEvent, TimeSource()->Now());
 	EventQueue()->AddEvent(nextBufferEvent);
-	uint32 dummy;
-	write_port(ControlPort(), -1, &dummy, sizeof(dummy));
 	
 	return B_OK;
 }
@@ -698,8 +659,6 @@ _SoundPlayNode::HandleStart(
 		//		this->HandleEvent(&firstBufferEvent, 0, false);
 		//
 		EventQueue()->AddEvent(firstBufferEvent);
-		uint32 dummy;
-		write_port(ControlPort(), -1, &dummy, sizeof(dummy));
 	}
 	return B_OK;
 }
@@ -772,16 +731,11 @@ _SoundPlayNode::FillNextBuffer(bigtime_t event_time)
 	CALLED();
 
 	// get a buffer from our buffer group
-	bigtime_t start = system_time();
-	BBuffer* buf = mBufferGroup->RequestBuffer(mOutput.format.u.raw_audio.buffer_size, BufferDuration() / 4);
-	bigtime_t delta = system_time() - start;
-	if (delta > 200)
-		printf("RequestBuffer took %Ld usec\n", delta);
+	BBuffer* buf = mBufferGroup->RequestBuffer(mOutput.format.u.raw_audio.buffer_size, BufferDuration() / 2);
 
 	// if we fail to get a buffer (for example, if the request times out), we skip this
 	// buffer and go on to the next, to avoid locking up the control thread
-	if (!buf)
-	{
+	if (!buf) {
 		printf("RequestBuffer failed\n");
 		return NULL;
 	}
@@ -798,11 +752,5 @@ _SoundPlayNode::FillNextBuffer(bigtime_t event_time)
 	hdr->size_used = mOutput.format.u.raw_audio.buffer_size;
 	hdr->time_source = TimeSource()->ID();
 	hdr->start_time = event_time;
-/*
-	DPRINTF("TimeSource()->Now() : %li\n", TimeSource()->Now());
-	DPRINTF("hdr->start_time : %li\n", hdr->start_time);
-	DPRINTF("mFramesSent : %li\n", mFramesSent);
-	DPRINTF("mOutput.format.u.raw_audio.frame_rate : %f\n", mOutput.format.u.raw_audio.frame_rate);
-*/	
 	return buf;
 }

src/kits/media/TimeSourceObject.cpp

@@ -18,7 +18,7 @@ TimeSourceObject::TimeSourceObject(const media_node &node)
  :	BMediaNode("some timesource object", node.node, node.kind),
 	BTimeSource(node.node)
 {
-	printf("TimeSourceObject::TimeSourceObject enter, id = %ld\n", node.node);
+	TRACE("TimeSourceObject::TimeSourceObject enter, id = %ld\n", node.node);
 	if (fControlPort > 0)
 		delete_port(fControlPort);
 	fControlPort = node.port;
@@ -41,7 +41,7 @@ if (node.node == NODE_SYSTEM_TIMESOURCE_ID) {
 	AddNodeKind(NODE_KIND_NO_REFCOUNTING);
 	fControlPort = SHADOW_TIMESOURCE_CONTROL_PORT; // XXX if we don't do this, we get a infinite loop somewhere. This needs to be debugged
 	
-	printf("TimeSourceObject::TimeSourceObject leave, node id %ld\n", fNodeID);
+	TRACE("TimeSourceObject::TimeSourceObject leave, node id %ld\n", fNodeID);
 }
 
 /* virtual */ status_t

src/kits/media/TimeSourceObjectManager.cpp

@@ -53,12 +53,13 @@ TimeSourceObjectManager::~TimeSourceObjectManager()
 void
 TimeSourceObjectManager::InitSystemTimeSource()
 {
+	CALLED();
 	BAutolock lock(fLock);
 
 	if (fSystemTimeSource != 0)
 		return;
 
-	printf("TimeSourceObjectManager::InitSystemTimeSource enter\n");
+	TRACE("TimeSourceObjectManager::InitSystemTimeSource enter\n");
 	
 	media_node node;
 	node.node = NODE_SYSTEM_TIMESOURCE_ID;
@@ -67,13 +68,14 @@ TimeSourceObjectManager::InitSystemTimeSource()
 	
 	fSystemTimeSource = new SystemTimeSourceObject(node);
 
-	printf("TimeSourceObjectManager::InitSystemTimeSource leave\n");
+	TRACE("TimeSourceObjectManager::InitSystemTimeSource leave\n");
 }
 
 
 BTimeSource *
 TimeSourceObjectManager::GetSystemTimeSource()
 {
+	CALLED();
 	BAutolock lock(fLock);
 
 	if (fSystemTimeSource == 0)

src/servers/media/DefaultManager.cpp

@@ -252,6 +252,8 @@ DefaultManager::FindPhysicalAudioOut()
 	for (int i = 0; i < count; i++) {
 		if (0 == strcmp(info[i].name, "None Out")) // skip the Null audio driver
 			continue;
+		if (0 == strcmp(info[i].name, "DV Output")) // skip the Firewire audio driver
+			continue;
 		printf("Default physical audio output \"%s\" created!\n", info[i].name);
 		fPhysicalAudioOut = info[i].node.node;
 		return;
@@ -280,6 +282,8 @@ DefaultManager::FindPhysicalAudioIn()
 	for (int i = 0; i < count; i++) {
 		if (0 == strcmp(info[i].name, "None In")) // skip the Null audio driver
 			continue;
+		if (0 == strcmp(info[i].name, "DV Input")) // skip the Firewire audio driver
+			continue;
 		printf("Default physical audio input \"%s\" created!\n", info[i].name);
 		fPhysicalAudioIn = info[i].node.node;
 		return;
@@ -327,6 +331,8 @@ DefaultManager::FindTimeSource()
 			// The BeOS R5 None Out node pretend to be a physical time source, that is pretty dumb
 			if (0 == strcmp(info[i].name, "None Out")) // skip the Null audio driver
 				continue;
+			if (0 == strcmp(info[i].name, "DV Output")) // skip the Firewire audio driver
+				continue;
 			printf("Default DAC timesource \"%s\" created!\n", info[i].name);
 			fTimeSource = info[i].node.node;
 			return;

src/servers/media/media_server.cpp

@@ -119,7 +119,7 @@ ServerApp::ServerApp()
 	gAppManager = new AppManager;
 	gNodeManager = new NodeManager;
 
-	control_port = create_port(64,"media_server port");
+	control_port = create_port(64, MEDIA_SERVER_PORT_NAME);
 	control_thread = spawn_thread(controlthread, "media_server control", 105, this);
 	resume_thread(control_thread);
 
@@ -174,10 +174,10 @@ ServerApp::QuitRequested()
 void
 ServerApp::StartSystemTimeSource()
 {
-	printf("StartSystemTimeSource enter\n");
+	TRACE("StartSystemTimeSource enter\n");
 	status_t rv;
 
-	printf("StartSystemTimeSource creating object\n");
+	TRACE("StartSystemTimeSource creating object\n");
 
 	// register a dummy node 
 	media_node node;
@@ -186,19 +186,19 @@ ServerApp::StartSystemTimeSource()
 	
 	ASSERT(node.node == NODE_SYSTEM_TIMESOURCE_ID);
 
-	printf("StartSystemTimeSource setting as default\n");
+	TRACE("StartSystemTimeSource setting as default\n");
 	
 	rv = gNodeManager->SetDefaultNode(SYSTEM_TIME_SOURCE, &node, NULL, NULL);
 	ASSERT(rv == B_OK);
 	
-	printf("StartSystemTimeSource leave\n");
+	TRACE("StartSystemTimeSource leave\n");
 }
 
 void 
 ServerApp::HandleMessage(int32 code, void *data, size_t size)
 {
 	status_t rv;
-	INFO("ServerApp::HandleMessage %#lx\n", code);
+	TRACE("ServerApp::HandleMessage %#lx enter\n", code);
 	switch (code) {
 		case SERVER_CHANGE_ADDON_FLAVOR_INSTANCES_COUNT:
 		{
@@ -556,6 +556,7 @@ ServerApp::HandleMessage(int32 code, void *data, size_t size)
 		default:
 			printf("media_server: received unknown message code %#08lx\n",code);
 	}
+	TRACE("ServerApp::HandleMessage %#lx leave\n", code);
 }
 
 int32
@@ -575,6 +576,7 @@ ServerApp::controlthread(void *arg)
 
 void ServerApp::MessageReceived(BMessage *msg)
 {
+	TRACE("ServerApp::MessageReceived %x enter\n", msg->what);
 	switch (msg->what) {
 		case MEDIA_SERVER_REQUEST_NOTIFICATIONS: gNotificationManager->EnqueueMessage(msg); break;
 		case MEDIA_SERVER_CANCEL_NOTIFICATIONS: gNotificationManager->EnqueueMessage(msg); break;
@@ -583,6 +585,7 @@ void ServerApp::MessageReceived(BMessage *msg)
 			printf("\nnew media server: unknown message received\n");
 			msg->PrintToStream();
 	}
+	TRACE("ServerApp::MessageReceived %x leave\n", msg->what);
 }
 
 int main()

src/servers/media_addon/main.cpp

@@ -105,7 +105,7 @@ MediaAddonServer::MediaAddonServer(const char *sig) :
 	mediaroster = BMediaRoster::Roster();
 	filemap = new Map<ino_t, media_addon_id>;
 	infomap = new Map<media_addon_id, AddOnInfo>;
-	control_port = create_port(64, "media_addon_server port");
+	control_port = create_port(64, MEDIA_ADDON_SERVER_PORT_NAME);
 	control_thread = spawn_thread(controlthread, "media_addon_server control", 12, this);
 	resume_thread(control_thread);
 }
@@ -252,7 +252,7 @@ MediaAddonServer::ScanAddOnFlavors(BMediaAddOn *addon)
 	
 	TRACE("MediaAddonServer::ScanAddOnFlavors: id %ld\n",addon->AddonID());
 	
-	port = find_port("media_server port");
+	port = find_port(MEDIA_SERVER_PORT_NAME);
 	if (port <= B_OK) {
 		FATAL("couldn't find media_server port\n");
 		return;