OK, here’s the best I can come up with – @Spacechild1 can correct me if I’m proposing something wrong.
-
In lang/LangPrimSource/OSCData.cpp, add these scprintf calls – non-scprintf lines are the original ones in the function; scprintf is the addition.
- makeSynthMsgWithTags() near the top:
if (GetTag(slots) == tagSym && slotRawSymbol(slots)->name[0] != '/') {
scprintf("makeSynthMsgWithTags name = %s\n", slotRawSymbol(slots)->name);
packet->adds_slpre(slotRawSymbol(slots)->name);
} else {
- makeSynthBundle() near the bottom:
packet->CloseBundle();
scprintf("makeSynthBundle for OSC timestamp %lx\n", oscTime);
return errNone;
- addMsgSlot() near the top (again, only scprintf lines are new):
static int addMsgSlot(big_scpacket* packet, PyrSlot* slot) {
switch (GetTag(slot)) {
case tagInt:
scprintf("addMsgSlot int = %d\n", slotRawInt(slot));
packet->addi(slotRawInt(slot));
break;
case tagSym:
scprintf("addMsgSlot sym = %s\n", slotRawSymbol(slot)->name);
packet->adds(slotRawSymbol(slot)->name);
break;
case tagObj:
if (isKindOf(slotRawObject(slot), class_string)) {
PyrString* stringObj = slotRawString(slot);
scprintf("addMsgSlot str = %s\n", stringObj->s);
packet->adds(stringObj->s, stringObj->size);
-
In server/scsynth/SC_CoreAudio.cpp:
- ProcessOSCPacket() at the top:
bool ProcessOSCPacket(World* inWorld, OSC_Packet* inPacket) {
// scprintf("ProcessOSCPacket %d, '%s'\n", inPacket->mSize, inPacket->mData);
if (!inPacket)
return false;
scprintf("ProcessOSCPacket at OSC timestamp %lx, '%s'\n", oscTimeNow(), inPacket->mData);
Then you would need to rebuild SC from sources. On my Ubuntu Studio machine, I don’t think I can build for macOS M1, so, you’d have to figure out how to do that yourself, or get someone to do it for you.
The OSCData.cpp changes should identify the command path and outgoing timestamp of each message going out. The SC_CoreAudio.cpp changes should identify bundled messages as #bundle, and give the OSC timestamp at the moment of receipt.
For example:
(
s.waitForBoot {
2.0.wait;
s.makeBundle(0.2, { Bus(\control, 0, 1, s).get });
1.0.wait;
s.quit;
}
)
There’s a lot of junk from status messages, but in the middle, there will be something like this:
ProcessOSCPacket at OSC timestamp ec11fa5b3c55ccc3, '/status'
ProcessOSCPacket at OSC timestamp ec11fa5b8f808377, '/status'
addMsgSlot str = /status
ProcessOSCPacket at OSC timestamp ec11fa5b90f76969, '/status'
makeSynthMsgWithTags name = c_get
makeSynthBundle for OSC timestamp 1
makeSynthMsgWithTags name = c_get
makeSynthBundle for OSC timestamp ec11fa5bd3c84e36
ProcessOSCPacket at OSC timestamp ec11fa5ba0baa369, '#bundle'
ProcessOSCPacket at OSC timestamp ec11fa5be2b0d8ee, '/status'
Bus control index: 0 value: 0.0.
ProcessOSCPacket at OSC timestamp ec11fa5c35e75d20, '/status'
The important bit:
makeSynthBundle for OSC timestamp ec11fa5bd3c84e36
ProcessOSCPacket at OSC timestamp ec11fa5ba0baa369, '#bundle'
So we know that the c_get message was sent with a timestamp to be executed at ec11fa5bd3c84e36, and it was received at timestamp ec11fa5ba0baa369.
Needs a little love to make it intelligible to humans:
(
// EDIT: remove reference to an extension method `hexToInt`
~hexToInt = { |hexStr|
var result = 0, i, digit;
hexStr.do { |char|
digit = char.digit;
if(digit.notNil) {
result = (result << 4) | digit;
} {
"Invalid hex digit found at % in %".format(char, hexStr).warn;
result = (result << 4);
};
};
result
};
~intAsUnsignedFloat = { |int|
int.asFloat.wrap(0.0, 2.0 ** 32)
};
~splitOSCTimestamp = { |uint64HexString|
var out;
uint64HexString = uint64HexString.toUpper;
if(uint64HexString.size < 16) {
uint64HexString = String.fill(16 - uint64HexString.size, $0) ++ uint64HexString;
};
out = (
secondsSince1900: ~intAsUnsignedFloat.(~hexToInt.(uint64HexString[0..7])),
fractionRawInt: ~intAsUnsignedFloat.(~hexToInt.(uint64HexString[8..15]))
);
out.put(\fraction, out[\fractionRawInt] * (2 ** -32))
};
)
// outgoing timestamp (desired execution time)
~splitOSCTimestamp.("ec11fa5bd3c84e36");
-> ('fractionRawInt': 3553119798.0, 'fraction': 0.82727516954765, 'secondsSince1900': 3960601179.0)
// timestamp at the moment of receipt in scsynth
~splitOSCTimestamp.("ec11fa5ba0baa369");
-> ('fractionRawInt': 2696586089.0, 'fraction': 0.62784787476994, 'secondsSince1900': 3960601179.0)
From this, we can read that the message was received almost exactly 200 ms before the desired execution time – which we would expect, since the s.makeBundle in the test code specified 0.2 sec latency.
A “late” message should happen if the receipt timestamp is later than the desired execution time (or maybe if it’s within hw-buffer-size before exec time).
What we are looking for, then, is inconsistency in either the outgoing or ingoing timestamps. If sclang’s clock is behaving inconsistently, then the “makeSynthBundle” timestamps will increase erratically. If it’s scsynth’s clock that is the problem, then the ProcessOSCPacket timestamps will be unpredictable. (ProcessOSCPacket would be affected by network jitter as well, but, on the same machine, UDP packet transmission should take less than 1 ms, so if the problem is on the receiving side, I’d assume first that it’s the clock.)
Now… is this a lot of effort to troubleshoot? Yes… but, it really seems to be something very weird about timing / timestamp internals. I don’t recall seeing this before. To look at internals that are not otherwise exposed, we have to do some weird sh—tuff.
IMO the issue does not have to do with blockSize, hardwareBufferSize, memory allocation or CPU load. I don’t think any progress can be made on this issue without identifying which side of the timing equation is misbehaving, and that means getting hands dirty… nobody likes this, but I don’t see another way. At least we have to rule it out.
hjh