bugfixes and debug information

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

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

@@ -529,6 +529,14 @@ 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,
 	// push it through the event looper
 	media_timed_event event(buffer->Header()->start_time,
@@ -540,10 +548,18 @@ AudioMixer::BufferReceived(BBuffer *buffer)
 
 
 void
-AudioMixer::HandleInputBuffer(BBuffer *buffer)
+AudioMixer::HandleInputBuffer(BBuffer *buffer, bigtime_t lateness)
 {
 	media_header *hdr = buffer->Header();
 
+	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();
 	
@@ -554,17 +570,11 @@ AudioMixer::HandleInputBuffer(BBuffer *buffer)
 		if (channel->fInput.destination.id != hdr->destination)
 			continue;
 
-		bigtime_t now = TimeSource()->Now();
-		bigtime_t perf_time = hdr->start_time;				
-		bigtime_t how_late = now - perf_time;
-		bigtime_t event_latency = EventLatency();
-		
-		if (how_late > (event_latency + 2000)) {
-			how_late -= event_latency;
-			printf("Received buffer %Ld usecs late from %s\n", how_late, channel->fInput.name);
+		if (how_late > 0) {
+			printf("Received buffer %Ld usecs late, lateness %Ld\n", how_late, lateness);
 			if (RunMode() != B_OFFLINE && RunMode() != B_RECORDING) {
 				printf("sending notify\n");
-				NotifyLateProducer(channel->fInput.source, max_c(500, how_late), perf_time);
+				NotifyLateProducer(channel->fInput.source, how_late, perf_time);
 			} else if (RunMode() == B_DROP_DATA) {
 				printf("dropping buffer\n");
 				return;
@@ -580,6 +590,9 @@ AudioMixer::HandleInputBuffer(BBuffer *buffer)
 				channel->fInput.format.u.raw_audio.frame_rate) * 
 				sample_size * channel->fInput.format.u.raw_audio.channel_count)) % int(channel->fDataSize);
 */
+		if (channel->fDataSize == 0)
+			break;
+			
 		size_t total_offset = int(channel->fEventOffset + channel->fInput.format.u.raw_audio.buffer_size)  % int(channel->fDataSize);
 		
 		char *indata = (char *)buffer->Data();
@@ -604,10 +617,14 @@ AudioMixer::HandleInputBuffer(BBuffer *buffer)
 void
 AudioMixer::SendNewBuffer(bigtime_t event_time)
 {
-
+	bigtime_t start = system_time();
 	BBuffer *outbuffer = fBufferGroup->RequestBuffer(fOutput.format.u.raw_audio.buffer_size, BufferDuration());
+	bigtime_t delta = system_time() - start;
+	if (delta > 200)
+		printf("RequestBuffer took %Ld usec\n", delta);
+
 	if (!outbuffer) {
-		printf("Could not allocate buffer\n");
+		printf("AudioMixer: Could not allocate buffer\n");
 		return;
 	}
 				
@@ -619,10 +636,14 @@ AudioMixer::SendNewBuffer(bigtime_t event_time)
 	outheader->time_source = TimeSource()->ID();
 	outheader->start_time = event_time;
 	
+	bigtime_t start2 = system_time();
 	if (B_OK != SendBuffer(outbuffer, fOutput.destination)) {
-		printf("Could not send buffer to output : %s\n", fOutput.name);
+		printf("AudioMixer: Could not send buffer to output : %s\n", fOutput.name);
 		outbuffer->Recycle();
 	}
+	bigtime_t delta2 = system_time() - start2;
+	if (delta2 > 200)
+		printf("SendBuffer took %Ld usec\n", delta2);
 }
 
 
@@ -648,6 +669,7 @@ status_t
 AudioMixer::GetLatencyFor( const media_destination &for_whom, bigtime_t *out_latency, 
 							media_node_id *out_timesource)
 {
+	printf("AudioMixer::GetLatencyFor\n");
 
 	if (! IsValidDest(for_whom))
 		return B_MEDIA_BAD_DESTINATION;
@@ -658,6 +680,8 @@ AudioMixer::GetLatencyFor( const media_destination &for_whom, bigtime_t *out_lat
 	*out_latency = EventLatency();
 	*out_timesource = TimeSource()->ID();
 
+	printf("AudioMixer::GetLatencyFor %Ld\n", EventLatency());
+
 	return B_OK;
 
 }
@@ -967,11 +991,12 @@ AudioMixer::SetBufferGroup(const media_source &for_source, BBufferGroup *newGrou
 status_t
 AudioMixer::GetLatency(bigtime_t *out_latency)
 {
-
 	// report our *total* latency:  internal plus downstream plus scheduling
 	*out_latency = EventLatency() + SchedulingLatency();
-	return B_OK;
 
+	printf("AudioMixer::GetLatency %Ld\n", *out_latency);
+
+	return B_OK;
 }
 
 status_t
@@ -1077,12 +1102,17 @@ 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);
+	fInternalLatency += 15000;
+	printf("Internal latency is %Ld usecs\n", fInternalLatency);
 	
 	delete mouse;
 	
 	// might need to tweak the latency
 	SetEventLatency(fLatency + fInternalLatency);
 	
+	printf("AudioMixer: SendLatencyChange %Ld\n", EventLatency());
+	SendLatencyChange(source, dest, EventLatency());
+
 	// calculate buffer duration and set it	
 	if (fOutput.format.u.raw_audio.frame_rate == 0) {
 		// XXX must be adjusted later when the format is known
@@ -1129,8 +1159,14 @@ AudioMixer::LateNoticeReceived(const media_source &what, bigtime_t how_much, big
 		if (RunMode() == B_INCREASE_LATENCY) {
 			fInternalLatency += how_much;
 
+//			if (fInternalLatency > 50000)
+//				fInternalLatency = 50000;
+
 			printf("AudioMixer: increasing internal latency to %Ld usec\n", fInternalLatency);
 			SetEventLatency(fLatency + fInternalLatency);
+		
+//			printf("AudioMixer: SendLatencyChange %Ld (2)\n", EventLatency());
+//			SendLatencyChange(source, dest, EventLatency());
 		}
 	}
 }
@@ -1198,7 +1234,7 @@ AudioMixer::HandleEvent( const media_timed_event *event, bigtime_t lateness, boo
 	
 		case BTimedEventQueue::B_HANDLE_BUFFER:
 		{
-			HandleInputBuffer((BBuffer *)event->pointer);
+			HandleInputBuffer((BBuffer *)event->pointer, lateness);
 			((BBuffer *)event->pointer)->Recycle();
 			break;
 		}
@@ -1316,9 +1352,9 @@ AudioMixer::AllocateBuffers()
 	size_t size = fOutput.format.u.raw_audio.buffer_size;
 	int32 count = int32((fLatency / (BufferDuration() + 1)) + 1);
 	
-	if (count < 2) {
+	if (count < 3) {
 		printf("AudioMixer: calculated only %ld buffers, that's not enough\n", count);
-		count = 2;
+		count = 3;
 	}
 	
 	printf("AudioMixer: allocating %ld buffers\n", count);

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

@@ -49,7 +49,7 @@ class AudioMixer :
 		status_t			FillMixBuffer(void *outbuffer, size_t size);
 		
 		void				SendNewBuffer(bigtime_t event_time);
-		void				HandleInputBuffer(BBuffer *buffer);
+		void				HandleInputBuffer(BBuffer *buffer, bigtime_t lateness);
 					
 	// BMediaNode methods
 

src/kits/media/MediaEventLooper.cpp

@@ -262,9 +262,9 @@ BMediaEventLooper::ControlLoop()
 		if (err == B_OK) {
 			bigtime_t lateness;
 			if (is_realtime)
-				lateness = TimeSource()->RealTime() - event.event_time - fEventLatency;
+				lateness = TimeSource()->RealTime() + fEventLatency - event.event_time;
 			else
-				lateness = TimeSource()->Now() - event.event_time - fEventLatency;
+				lateness = TimeSource()->Now() + fEventLatency - event.event_time;
 			DispatchEvent(&event, lateness, is_realtime);
 		}
 	}

src/kits/media/MediaNode.cpp

@@ -661,6 +661,7 @@ BMediaNode::HandleMessage(int32 message,
 				fTimeSource->AddMe(this);
 			}
 			TRACE("BMediaNode::HandleMessage NODE_SET_TIMESOURCE: node %ld has been assigned time source %ld\n", ID(), fTimeSource->ID());
+			printf("BMediaNode::HandleMessage NODE_SET_TIMESOURCE: node %ld has been assigned time source %ld\n", ID(), fTimeSource->ID());
 			
 			//roster->StartTimeSource(fTimeSource->Node(), fTimeSource->RealTime());
 			return B_OK;

src/kits/media/SoundPlayNode.cpp

@@ -13,7 +13,7 @@
 #include "SoundPlayNode.h"
 #include "debug.h"
 
-#define DPRINTF 0
+#define DPRINTF 1
 
 #if DPRINTF
 	#undef DPRINTF
@@ -23,6 +23,8 @@
 	#define DPRINTF if (1) {} else printf
 #endif
 
+#define SEND_NEW_BUFFER_EVENT (BTimedEventQueue::B_USER_EVENT + 1)
+
 _SoundPlayNode::_SoundPlayNode(const char *name, const media_multi_audio_format *format, BSoundPlayer *player) : 
 	BMediaNode(name),
 	BBufferProducer(B_MEDIA_RAW_AUDIO),
@@ -35,8 +37,8 @@ _SoundPlayNode::_SoundPlayNode(const char *name, const media_multi_audio_format
 	mTooEarlyCount(0)
 {
 	CALLED();
-	mPreferredFormat.type = B_MEDIA_RAW_AUDIO;
-	mPreferredFormat.u.raw_audio = *format;
+	mFormat.type = B_MEDIA_RAW_AUDIO;
+	mFormat.u.raw_audio = *format;
 	
 	DPRINTF("Format Info:\n");
 	DPRINTF("  frame_rate:     %f\n",mFormat.u.raw_audio.frame_rate);
@@ -112,7 +114,7 @@ void _SoundPlayNode::NodeRegistered(void)
 	
 	SetPriority(B_URGENT_PRIORITY);
 	
-	mOutput.format = mPreferredFormat;
+	mOutput.format = mFormat;
 	mOutput.destination = media_destination::null;
 	mOutput.source.port = ControlPort();
 	mOutput.source.id = 1;
@@ -161,7 +163,7 @@ _SoundPlayNode::FormatSuggestionRequested(media_type type, int32 /*quality*/, me
 	}
 
 	// this is the format we'll be returning (our preferred format)
-	*format = mPreferredFormat;
+	*format = mFormat;
 
 	// a wildcard type is okay; we can specialize it
 	if (type == B_MEDIA_UNKNOWN_TYPE)
@@ -190,7 +192,7 @@ _SoundPlayNode::FormatProposal(const media_source& output, media_format* format)
 	// we only support floating-point raw audio, so we always return that, but we
 	// supply an error code depending on whether we found the proposal acceptable.
 	media_type requestedType = format->type;
-	*format = mPreferredFormat;
+	*format = mFormat;
 	if ((requestedType != B_MEDIA_UNKNOWN_TYPE) && (requestedType != B_MEDIA_RAW_AUDIO))
 	{
 		fprintf(stderr, "_SoundPlayNode::FormatProposal returning B_MEDIA_BAD_FORMAT\n");
@@ -354,7 +356,7 @@ _SoundPlayNode::Connect(status_t error, const media_source& source, const media_
 	if (error)
 	{
 		mOutput.destination = media_destination::null;
-		mOutput.format = mPreferredFormat;
+		mOutput.format = mFormat;
 		return;
 	}
 
@@ -370,7 +372,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 = 5000LL;
+	mInternalLatency = 1000LL;
 	fprintf(stderr, "\tbuffer-filling took %Ld usec on this machine\n", mInternalLatency);
 	SetEventLatency(mLatency + mInternalLatency);
 
@@ -406,7 +408,7 @@ _SoundPlayNode::Disconnect(const media_source& what, const media_destination& wh
 	if ((where == mOutput.destination) && (what == mOutput.source))
 	{
 		mOutput.destination = media_destination::null;
-		mOutput.format = mPreferredFormat;
+		mOutput.format = mFormat;
 		delete mBufferGroup;
 		mBufferGroup = NULL;
 	}
@@ -450,8 +452,11 @@ _SoundPlayNode::LateNoticeReceived(const media_source& what, bigtime_t how_much,
 		// not properly reporting their latency, but there's not much we can do about
 		// that at the moment, so we try to start producing buffers earlier to
 		// compensate.
-//		mInternalLatency += how_much;
-		mLatency += 1000;
+		mInternalLatency += how_much;
+
+//		if (mInternalLatency > 50000)
+//			mInternalLatency = 50000;
+
 		SetEventLatency(mLatency + mInternalLatency);
 
 		fprintf(stderr, "\tincreasing latency to %Ld\n", mLatency + mInternalLatency);
@@ -500,6 +505,8 @@ _SoundPlayNode::LatencyChanged(const media_source& source, const media_destinati
 {
 	CALLED();
 	
+	printf("_SoundPlayNode::LatencyChanged: new_latency %Ld\n", new_latency);
+	
 	// something downstream changed latency, so we need to start producing
 	// buffers earlier (or later) than we were previously.  Make sure that the
 	// connection that changed is ours, and adjust to the new downstream
@@ -508,6 +515,8 @@ _SoundPlayNode::LatencyChanged(const media_source& source, const media_destinati
 	{
 		mLatency = new_latency;
 		SetEventLatency(mLatency + mInternalLatency);
+	} else {
+		printf("_SoundPlayNode::LatencyChanged: ignored\n");
 	}
 }
 
@@ -535,8 +544,11 @@ void _SoundPlayNode::HandleEvent(
 			HandleStop(event,lateness,realTimeEvent);
 			break;
 		case BTimedEventQueue::B_HANDLE_BUFFER:
+			// we don't get any buffers
+			break;
+		case SEND_NEW_BUFFER_EVENT:
 			if (RunState() == BMediaEventLooper::B_STARTED) {
-				HandleBuffer(event,lateness,realTimeEvent);
+				SendNewBuffer(event, lateness, realTimeEvent);
 			}
 			break;
 		case BTimedEventQueue::B_DATA_STATUS:
@@ -556,12 +568,15 @@ void _SoundPlayNode::HandleEvent(
 // how should we handle late buffers?  drop them?
 // notify the producer?
 status_t 
-_SoundPlayNode::HandleBuffer(
+_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))
@@ -574,7 +589,7 @@ _SoundPlayNode::HandleBuffer(
 	bigtime_t scheduling_latency = SchedulingLatency();
 
 	if (lateness > 0) {
-		printf("_SoundPlayNode::HandleBuffer, event sheduled too late, lateness is %Ld\n", lateness);
+		printf("_SoundPlayNode::SendNewBuffer, event sheduled too late, lateness is %Ld\n", lateness);
 		mInternalLatency += 1000;
 		SetEventLatency(mLatency + mInternalLatency);
 	}
@@ -588,40 +603,51 @@ _SoundPlayNode::HandleBuffer(
 		if (buffer) {
 
 			// If we are ready way too early, decrase internal latency
-			bigtime_t how_early = event->event_time - TimeSource()->Now() - mLatency;
-			if (how_early > (3 * scheduling_latency)) {
+/*
+			bigtime_t how_early = event->event_time - TimeSource()->Now() - mLatency - mInternalLatency;
+			if (how_early > 5000) {
 
-				printf("_SoundPlayNode::HandleBuffer, event scheduled too early, how_early is %Ld\n", how_early);
+				printf("_SoundPlayNode::SendNewBuffer, event scheduled too early, how_early is %Ld\n", how_early);
 
 				if (mTooEarlyCount++ == 5) {
 					mInternalLatency -= how_early;
 					if (mInternalLatency < 500)
 						mInternalLatency = 500;
-					printf("_SoundPlayNode::HandleBuffer setting internal latency to %Ld\n", mInternalLatency);
+					printf("_SoundPlayNode::SendNewBuffer setting internal latency to %Ld\n", mInternalLatency);
 					SetEventLatency(mLatency + mInternalLatency);
 					mTooEarlyCount = 0;
 				}
 			}
-
+*/
 			// 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);
 		}
 	}
 
 	// track how much media we've delivered so far
 	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;
+		/ ((mOutput.format.u.raw_audio.format & media_raw_audio_format::B_AUDIO_SIZE_MASK)
+		* mOutput.format.u.raw_audio.channel_count);
 	mFramesSent += nFrames;
 
 	// The buffer is on its way; now schedule the next one to go
 	// nextEvent is the time at which the buffer should arrive at it's destination
-	bigtime_t nextEvent = mStartTime + bigtime_t(double(mFramesSent) / double(mOutput.format.u.raw_audio.frame_rate) * 1000000.0);
-	media_timed_event nextBufferEvent(nextEvent, BTimedEventQueue::B_HANDLE_BUFFER);
+	bigtime_t nextEvent = mStartTime + bigtime_t((1000000LL * mFramesSent) / mOutput.format.u.raw_audio.frame_rate);
+	media_timed_event nextBufferEvent(nextEvent, SEND_NEW_BUFFER_EVENT);
+	if (TimeSource()->Now() + mLatency > nextEvent) {
+		printf("SendNewBuffer: already %Ld usec too late for new buffer\n", TimeSource()->Now() + mLatency - nextEvent);
+	}
+//	printf("0) should arrive at %20Ld, now %20Ld\n", nextEvent, TimeSource()->Now());
 	EventQueue()->AddEvent(nextBufferEvent);
 	
 	return B_OK;
@@ -660,8 +686,10 @@ _SoundPlayNode::HandleStart(
 	{
 		// We want to start sending buffers now, so we set up the buffer-sending bookkeeping
 		// and fire off the first "produce a buffer" event.
+	
+		mFramesSent = 0;	
 		mStartTime = event->event_time;
-		media_timed_event firstBufferEvent(mStartTime, BTimedEventQueue::B_HANDLE_BUFFER);
+		media_timed_event firstBufferEvent(mStartTime, SEND_NEW_BUFFER_EVENT);
 
 		// Alternatively, we could call HandleEvent() directly with this event, to avoid a trip through
 		// the event queue, like this:
@@ -702,7 +730,7 @@ _SoundPlayNode::HandleStop(
 {
 	CALLED();
 	// flush the queue so downstreamers don't get any more
-	EventQueue()->FlushEvents(0, BTimedEventQueue::B_ALWAYS, true, BTimedEventQueue::B_HANDLE_BUFFER);
+	EventQueue()->FlushEvents(0, BTimedEventQueue::B_ALWAYS, true, SEND_NEW_BUFFER_EVENT);
 	
 	return B_OK;
 }
@@ -729,8 +757,8 @@ _SoundPlayNode::AllocateBuffers()
 	DPRINTF("\tlatency = %Ld, buffer duration = %Ld\n", mLatency, BufferDuration());
 	DPRINTF("\tcreating group of %ld buffers, size = %lu\n", count, size);
 	
-	if (count < 2)
-		count == 2;
+	if (count < 3)
+		count == 3;
 	
 	mBufferGroup = new BBufferGroup(size, count);
 }
@@ -741,7 +769,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());
+	bigtime_t delta = system_time() - start;
+	if (delta > 200)
+		printf("RequestBuffer took %Ld usec\n", delta);
 
 	// 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
@@ -762,11 +794,11 @@ _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/SoundPlayNode.h

@@ -140,7 +140,7 @@ virtual status_t HandleStop(
 						const media_timed_event *event,
 						bigtime_t lateness,
 						bool realTimeEvent = false);
-virtual status_t HandleBuffer(
+virtual status_t SendNewBuffer(
 						const media_timed_event *event,
 						bigtime_t lateness,
 						bool realTimeEvent = false);
@@ -163,7 +163,6 @@ private:
 	bool 				mOutputEnabled;
 	media_output		mOutput;
 	BBufferGroup		*mBufferGroup;
-	media_format 		mPreferredFormat;
 	media_format		mFormat;
 	bigtime_t 			mLatency;
 	bigtime_t 			mInternalLatency;

src/kits/media/TimeSource.cpp

@@ -168,6 +168,7 @@ BTimeSource::GetTime(bigtime_t *performance_time,
 //		*drift = 1.0f;
 //		return B_OK;
 //	}
+	//printf("BTimeSource::GetTime timesource %ld, index %ld, perf %16Ld, real %16Ld, drift %2.2f\n", ID(), index, *performance_time, *real_time, *drift);
 
 	TRACE_TIMESOURCE("BTimeSource::GetTime     timesource %ld, perf %16Ld, real %16Ld, drift %2.2f\n", ID(), *performance_time, *real_time, *drift);
 	return B_OK;
@@ -292,6 +293,8 @@ BTimeSource::PublishTime(bigtime_t performance_time,
 	fBuf->perftime[index] = performance_time;
 	fBuf->drift[index] = drift;
 	atomic_add(&fBuf->readindex, 1);
+
+	//printf("BTimeSource::PublishTime timesource %ld, index %ld, perf %16Ld, real %16Ld, drift %2.2f\n", ID(), fBuf->readindex, performance_time, real_time, drift);
 }