1function [t, TS] = plotReceiveTrace(filename, flat) 2fid=fopen(filename); 3%DEBUG ; ( 8:32:33:375 | 0) VIDEO:1 ; 5260; First packet of frame 1869537938 4%DEBUG ; ( 8:32:33:375 | 0) VIDEO CODING:1 ; 5260; Decoding timestamp 1869534934 5%DEBUG ; ( 8:32:33:375 | 0) VIDEO:1 ; 5260; Render frame 1869534934 at 20772610 6%DEBUG ; ( 8:32:33:375 | 0) VIDEO CODING:-1 ; 5260; Frame decoded: timeStamp=1870511259 decTime=0 maxDecTime=0, at 19965 7%DEBUG ; ( 7:59:42:500 | 0) VIDEO:-1 ; 2500; Received complete frame timestamp 1870514263 frame type 1 frame size 7862 at time 19965, jitter estimate was 130 8%DEBUG ; ( 8: 5:51:774 | 0) VIDEO:-1 ; 3968; ExtrapolateLocalTime(1870967878)=24971 ms 9 10if nargin == 1 11 flat = 0; 12end 13line = fgetl(fid); 14estimatedArrivalTime = []; 15packetTime = []; 16firstPacketTime = []; 17decodeTime = []; 18decodeCompleteTime = []; 19renderTime = []; 20completeTime = []; 21while ischar(line)%line ~= -1 22 if length(line) == 0 23 line = fgetl(fid); 24 continue; 25 end 26 % Parse the trace line header 27 [tempres, count] = sscanf(line, 'DEBUG ; (%u:%u:%u:%u |%*lu)%13c:'); 28 if count < 5 29 line = fgetl(fid); 30 continue; 31 end 32 hr=tempres(1); 33 mn=tempres(2); 34 sec=tempres(3); 35 ms=tempres(4); 36 timeInMs=hr*60*60*1000 + mn*60*1000 + sec*1000 + ms; 37 label = tempres(5:end); 38 I = find(label ~= 32); 39 label = label(I(1):end); % remove white spaces 40 if ~strncmp(char(label), 'VIDEO', 5) & ~strncmp(char(label), 'VIDEO CODING', 12) 41 line = fgetl(fid); 42 continue; 43 end 44 message = line(72:end); 45 46 % Parse message 47 [p, count] = sscanf(message, 'ExtrapolateLocalTime(%lu)=%lu ms'); 48 if count == 2 49 estimatedArrivalTime = [estimatedArrivalTime; p']; 50 line = fgetl(fid); 51 continue; 52 end 53 54 [p, count] = sscanf(message, 'Packet seqNo %u of frame %lu at %lu'); 55 if count == 3 56 packetTime = [packetTime; p']; 57 line = fgetl(fid); 58 continue; 59 end 60 61 [p, count] = sscanf(message, 'First packet of frame %lu at %lu'); 62 if count == 2 63 firstPacketTime = [firstPacketTime; p']; 64 line = fgetl(fid); 65 continue; 66 end 67 68 [p, count] = sscanf(message, 'Decoding timestamp %lu at %lu'); 69 if count == 2 70 decodeTime = [decodeTime; p']; 71 line = fgetl(fid); 72 continue; 73 end 74 75 [p, count] = sscanf(message, 'Render frame %lu at %lu. Render delay %lu, required delay %lu, max decode time %lu, min total delay %lu'); 76 if count == 6 77 renderTime = [renderTime; p']; 78 line = fgetl(fid); 79 continue; 80 end 81 82 [p, count] = sscanf(message, 'Frame decoded: timeStamp=%lu decTime=%d maxDecTime=%lu, at %lu'); 83 if count == 4 84 decodeCompleteTime = [decodeCompleteTime; p']; 85 line = fgetl(fid); 86 continue; 87 end 88 89 [p, count] = sscanf(message, 'Received complete frame timestamp %lu frame type %u frame size %*u at time %lu, jitter estimate was %lu'); 90 if count == 4 91 completeTime = [completeTime; p']; 92 line = fgetl(fid); 93 continue; 94 end 95 96 line = fgetl(fid); 97end 98fclose(fid); 99 100t = completeTime(:,3); 101TS = completeTime(:,1); 102 103figure; 104subplot(211); 105hold on; 106slope = 0; 107 108if sum(size(packetTime)) > 0 109 % Plot the time when each packet arrives 110 firstTimeStamp = packetTime(1,2); 111 x = (packetTime(:,2) - firstTimeStamp)/90; 112 if flat 113 slope = x; 114 end 115 firstTime = packetTime(1,3); 116 plot(x, packetTime(:,3) - firstTime - slope, 'b.'); 117else 118 % Plot the time when the first packet of a frame arrives 119 firstTimeStamp = firstPacketTime(1,1); 120 x = (firstPacketTime(:,1) - firstTimeStamp)/90; 121 if flat 122 slope = x; 123 end 124 firstTime = firstPacketTime(1,2); 125 plot(x, firstPacketTime(:,2) - firstTime - slope, 'b.'); 126end 127 128% Plot the frame complete time 129if prod(size(completeTime)) > 0 130 x = (completeTime(:,1) - firstTimeStamp)/90; 131 if flat 132 slope = x; 133 end 134 plot(x, completeTime(:,3) - firstTime - slope, 'ks'); 135end 136 137% Plot the time the decode starts 138if prod(size(decodeTime)) > 0 139 x = (decodeTime(:,1) - firstTimeStamp)/90; 140 if flat 141 slope = x; 142 end 143 plot(x, decodeTime(:,2) - firstTime - slope, 'r.'); 144end 145 146% Plot the decode complete time 147if prod(size(decodeCompleteTime)) > 0 148 x = (decodeCompleteTime(:,1) - firstTimeStamp)/90; 149 if flat 150 slope = x; 151 end 152 plot(x, decodeCompleteTime(:,4) - firstTime - slope, 'g.'); 153end 154 155if prod(size(renderTime)) > 0 156 % Plot the wanted render time in ms 157 x = (renderTime(:,1) - firstTimeStamp)/90; 158 if flat 159 slope = x; 160 end 161 plot(x, renderTime(:,2) - firstTime - slope, 'c-'); 162 163 % Plot the render time if there were no render delay or decoding delay. 164 x = (renderTime(:,1) - firstTimeStamp)/90; 165 if flat 166 slope = x; 167 end 168 plot(x, renderTime(:,2) - firstTime - slope - renderTime(:, 3) - renderTime(:, 5), 'c--'); 169 170 % Plot the render time if there were no render delay. 171 x = (renderTime(:,1) - firstTimeStamp)/90; 172 if flat 173 slope = x; 174 end 175 plot(x, renderTime(:,2) - firstTime - slope - renderTime(:, 3) - renderTime(:, 5), 'b-'); 176end 177 178%plot(x, 90*x, 'r-'); 179 180xlabel('RTP timestamp (in ms)'); 181ylabel('Time (ms)'); 182legend('Packet arrives', 'Frame complete', 'Decode', 'Decode complete', 'Time to render', 'Only jitter', 'Must decode'); 183 184% subplot(312); 185% hold on; 186% completeTs = completeTime(:, 1); 187% arrivalTs = estimatedArrivalTime(:, 1); 188% [c, completeIdx, arrivalIdx] = intersect(completeTs, arrivalTs); 189% %plot(completeTs(completeIdx), completeTime(completeIdx, 3) - estimatedArrivalTime(arrivalIdx, 2)); 190% timeUntilComplete = completeTime(completeIdx, 3) - estimatedArrivalTime(arrivalIdx, 2); 191% devFromAvgCompleteTime = timeUntilComplete - mean(timeUntilComplete); 192% plot(completeTs(completeIdx) - completeTs(completeIdx(1)), devFromAvgCompleteTime); 193% plot(completeTime(:, 1) - completeTime(1, 1), completeTime(:, 4), 'r'); 194% plot(decodeCompleteTime(:, 1) - decodeCompleteTime(1, 1), decodeCompleteTime(:, 2), 'g'); 195% plot(decodeCompleteTime(:, 1) - decodeCompleteTime(1, 1), decodeCompleteTime(:, 3), 'k'); 196% xlabel('RTP timestamp'); 197% ylabel('Time (ms)'); 198% legend('Complete time - Estimated arrival time', 'Desired jitter buffer level', 'Actual decode time', 'Max decode time', 0); 199 200if prod(size(renderTime)) > 0 201 subplot(212); 202 hold on; 203 firstTime = renderTime(1, 1); 204 targetDelay = max(renderTime(:, 3) + renderTime(:, 4) + renderTime(:, 5), renderTime(:, 6)); 205 plot(renderTime(:, 1) - firstTime, renderTime(:, 3), 'r-'); 206 plot(renderTime(:, 1) - firstTime, renderTime(:, 4), 'b-'); 207 plot(renderTime(:, 1) - firstTime, renderTime(:, 5), 'g-'); 208 plot(renderTime(:, 1) - firstTime, renderTime(:, 6), 'k-'); 209 plot(renderTime(:, 1) - firstTime, targetDelay, 'c-'); 210 xlabel('RTP timestamp'); 211 ylabel('Time (ms)'); 212 legend('Render delay', 'Jitter delay', 'Decode delay', 'Extra delay', 'Min total delay'); 213end