Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

extreme SRTIO latency when SED depth is exceeded #1987

Open
jbqubit opened this issue Nov 5, 2022 · 8 comments
Open

extreme SRTIO latency when SED depth is exceeded #1987

jbqubit opened this issue Nov 5, 2022 · 8 comments

Comments

@jbqubit
Copy link
Contributor

jbqubit commented Nov 5, 2022

One-Line Summary

The Serial Event Dispatcher (SED) is a mechanism that enables RTIO PHYs to use a shared pool of FIFOs for queuing RTIO events -- SED was proposed here. The SED FIFOs supports some number of distinct RTIO timestamps (depth) and multiple simultaneous events at each timestamp (width). We observe that when events are scheduled that saturate the SED depth limit there is surprising and undesirable behavior.

  1. There is no error emitted.
  2. The core device experiences a poorly bounded, sometimes extreme delay.
  3. The core device has anomalous high latency when scheduling the first event.

Issue Details

In a test program (detailed below) a single RTIO channel is populated in a loop. After SED depth is saturated (event 64) the core device blocks for a 835 us. The second time the SED depth is saturated (event 128) the core device blocks for 63,901 us. The blocking continues with anomalous high durations at subsequent multiples of the SED depth.

Steps to Reproduce

from artiq.experiment import *
import numpy as np

class CoreDeviceProcessDurationsJWB(EnvExperiment):
  
   kernel_invariants = {"ftw0", "asf0", 'mindelay'}

   def build(self):
       self.trials = 200
       self.setattr_device("core")
       self.setattr_device("ttl7")
       self.ttl = self.ttl7
       self.urukul_channel = self.get_device('urukul1_ch3')
       self.urukul_switch = self.get_device('ttl_urukul1_sw3')
       self.zotino = self.get_device('zotino0')

       self.ftw0 = self.urukul_channel.frequency_to_ftw(100*MHz)
       self.asf0 = self.urukul_channel.amplitude_to_asf(0.85)
       self.mindelay = 8*ns

   def prepare(self):
       self.durations = np.full(self.trials, 0, dtype=np.int64)

   def print_results(self, test_name, durations):
       s = "### {} ### \n".format(test_name)
       mean = np.mean(durations)
       std = np.std(durations)
       maxdev = np.max(durations) - np.min(durations)
       maxfdev = (np.max(durations) - np.min(durations)) / np.mean(durations)
       deviations_found = 0
       for i in range(len(durations)):
           s += "{:3}: {:9}, ".format(i, durations[i])
           if (i+1)%8 == 0:
               s += '\n'
       s = s + "\nmean: {:9.0f}, std: {:9.0f}, max deviation: {:9.0f}, max frac deviation: {:.3f}\n".format(
           mean, std, maxdev, maxfdev)
       print(s)

   def run(self):
       tests = ['test_ttl_pulse']
       for test in tests:
           testf = getattr(self, test)
           durations = self.timer(testf)
           self.print_results(test, durations)

   @kernel
   def timer(self, kernel_method):
       self.core.reset()
       delay(1*ms)
       for i in range(self.trials):
           t1 = self.core.get_rtio_counter_mu()
           td = kernel_method()
           delay(td)  # default td=self.mindelay, required so kernel_method() is not, in general, optimized away 
           t2 = self.core.get_rtio_counter_mu()
           self.durations[i] = t2 - t1
       return self.durations

   @kernel
   def test_ttl_pulse(self):
       self.ttl.pulse(self.mindelay)
       return self.mindelay

Expected Behavior

SED is not well documented so my expectations can't be said to deviate from technical specifications. Generally, I can say say what I do and don't expect.

  • I don't expect the core device to block for longer than self.mindelay*depth
  • I do expect the core device to resume stuffing the SED FIFOS as soon as there is space available

Actual (undesired) Behavior

$ artiq_run repository/calibration/core_device_process_durations_jwb.py
### test_ttl_pulse ###
  0:  	4200,   1:  	1288,   2:  	1168,   3:   	952,   4:   	936,   5:   	936,   6:   	936,   7:   	936,
  8:   	936,   9:   	936,  10:   	936,  11:   	936,  12:   	936,  13:   	936,  14:   	936,  15:   	936,
 16:   	936,  17:   	936,  18:   	936,  19:   	936,  20:   	936,  21:   	936,  22:   	936,  23:   	936,
 24:   	936,  25:   	936,  26:   	936,  27:   	936,  28:   	936,  29:   	936,  30:   	936,  31:   	936,
 32:   	936,  33:   	936,  34:   	936,  35:   	936,  36:   	936,  37:   	936,  38:   	936,  39:   	936,
 40:   	936,  41:   	936,  42:   	936,  43:   	936,  44:   	936,  45:   	936,  46:   	936,  47:   	936,
 48:   	936,  49:   	936,  50:   	936,  51:   	936,  52:   	936,  53:   	936,  54:   	936,  55:   	936,
 56:   	936,  57:   	936,  58:   	936,  59:   	936,  60:   	936,  61:   	936,  62:   	936,  63:   	936,
 64:	835600,  65:   	936,  66:   	936,  67:   	936,  68:   	928,  69:   	936,  70:   	936,  71:   	936,
 72:   	936,  73:   	936,  74:   	936,  75:   	936,  76:   	936,  77:   	936,  78:   	936,  79:   	936,
 80:   	936,  81:   	936,  82:   	936,  83:   	936,  84:   	936,  85:   	936,  86:   	936,  87:   	936,
 88:   	936,  89:   	936,  90:   	936,  91:   	936,  92:   	936,  93:   	936,  94:   	936,  95:   	936,
 96:   	936,  97:   	936,  98:   	936,  99:   	936, 100:   	936, 101:   	936, 102:   	936, 103:   	936,
104:   	936, 105:   	936, 106:   	936, 107:   	936, 108:   	936, 109:   	936, 110:   	936, 111:   	928,
112:   	936, 113:   	936, 114:   	936, 115:   	936, 116:   	936, 117:   	936, 118:   	936, 119:   	936,
120:   	936, 121:   	936, 122:   	936, 123:   	936, 124:   	936, 125:   	936, 126:   	936, 127:   	936,
128:  63901288, 129:   	936, 130:   	936, 131:   	936, 132:   	936, 133:   	936, 134:   	936, 135:   	936,
136:   	928, 137:   	936, 138:   	936, 139:   	936, 140:   	936, 141:   	936, 142:   	936, 143:   	936,
144:   	936, 145:   	936, 146:   	936, 147:   	936, 148:   	936, 149:   	936, 150:   	936, 151:   	936,
152:   	936, 153:   	936, 154:   	936, 155:   	936, 156:   	936, 157:   	936, 158:   	936, 159:   	936,
160:   	936, 161:   	936, 162:   	936, 163:   	936, 164:   	936, 165:   	936, 166:   	928, 167:   	928,
168:   	936, 169:   	936, 170:   	936, 171:   	936, 172:   	936, 173:   	936, 174:   	936, 175:   	936,
176:   	936, 177:   	936, 178:   	936, 179:   	936, 180:   	936, 181:   	936, 182:   	936, 183:   	936,
184:   	936, 185:   	936, 186:   	936, 187:   	936, 188:   	936, 189:   	936, 190:   	936, 191:   	936,
192:   	936, 193:  64900232, 194:   	936, 195:   	936, 196:   	936, 197:   	936, 198:   	936, 199:   	936,

mean:	649127, std:   6407745, max deviation:  64899304, max frac deviation: 99.979 

Your System (omit irrelevant parts)

  • Operating System:
  • ARTIQ version: latest commit of tag version 7
  • Environment is nix shell
  • Hardware involved: Kasli v1.x
@sbourdeauducq
Copy link
Member

sbourdeauducq commented Nov 6, 2022

Simplified the code and increased the delays to something more reasonable (otherwise it understandably underflows).

from artiq.experiment import *

class Delays(EnvExperiment):
    def build(self):
        self.setattr_device("core")
        self.setattr_device("ttl0")

    def report(self, delays):
        for i, d in enumerate(delays):
            print("{:4d}:{:>6.2f}us".format(i, d/1000), end=" " if i % 5 != 4 else "\n")

    @kernel
    def run(self):
        count = 400
        delays = [0]*count
        self.core.reset()
        for i in range(count):
            t1 = self.core.get_rtio_counter_mu()
            self.ttl0.pulse(1*us)
            delay(1*us)
            t2 = self.core.get_rtio_counter_mu()
            delays[i] = t2-t1
        self.report(delays)

Event submission times look OK:

   0:  1.54us    1:  0.89us    2:  0.89us    3:  0.89us    4:  0.89us
   5:  0.89us    6:  0.89us    7:  0.89us    8:  0.89us    9:  0.89us
  10:  0.89us   11:  0.89us   12:  0.89us   13:  0.89us   14:  0.89us
  15:  0.89us   16:  0.89us   17:  0.89us   18:  0.89us   19:  0.89us
  20:  0.89us   21:  0.89us   22:  0.89us   23:  0.89us   24:  0.89us
  25:  0.89us   26:  0.89us   27:  0.89us   28:  0.89us   29:  0.89us
  30:  0.89us   31:  0.89us   32:  0.89us   33:  0.89us   34:  0.89us
  35:  0.89us   36:  0.89us   37:  0.89us   38:  0.89us   39:  0.89us
  40:  0.89us   41:  0.89us   42:  0.89us   43:  0.89us   44:  0.89us
  45:  0.89us   46:  0.89us   47:  0.89us   48:  0.89us   49:  0.89us
  50:  0.89us   51:  0.89us   52:  0.89us   53:  0.89us   54:  0.89us
  55:  0.89us   56:  0.89us   57:  0.89us   58:  0.89us   59:  0.89us
  60:  0.89us   61:  0.89us   62:  0.89us   63:  0.89us   64: 40.06us
  65:  0.89us   66:  0.89us   67:  0.89us   68:  0.89us   69:  0.89us
  70:  0.89us   71:  0.89us   72:  0.89us   73:  0.89us   74:  0.89us
  75:  0.89us   76:  0.89us   77:  0.89us   78:  0.89us   79:  0.89us
  80:  0.89us   81:  0.89us   82:  0.89us   83:  0.89us   84:  0.89us
  85:  0.89us   86:  0.89us   87:  0.89us   88:  0.89us   89:  0.89us
  90:  0.89us   91:  0.89us   92:  0.89us   93:  0.89us   94:  0.89us
  95:  0.89us   96:  0.89us   97:  0.89us   98:  0.89us   99:  0.89us
 100:  0.89us  101:  0.89us  102:  0.89us  103:  0.89us  104:  0.89us
 105:  0.89us  106:  0.89us  107:  0.89us  108:  0.89us  109:  0.89us
 110:  0.89us  111:  0.89us  112:  0.89us  113:  0.89us  114:  0.89us
 115:  0.89us  116:  0.89us  117:  0.89us  118:  0.89us  119:  0.89us
 120:  0.89us  121:  0.89us  122:  0.89us  123:  0.89us  124:  0.89us
 125:  0.89us  126:  0.89us  127:  0.89us  128: 45.27us  129:  0.89us
 130:  0.89us  131:  0.89us  132:  0.89us  133:  0.89us  134:  0.89us
 135:  0.89us  136:  0.89us  137:  0.89us  138:  0.89us  139:  0.89us
 140:  0.89us  141:  0.89us  142:  0.89us  143:  0.89us  144:  0.89us
 145:  0.89us  146:  0.89us  147:  0.89us  148:  0.89us  149:  0.89us
 150:  0.89us  151:  0.89us  152:  0.89us  153:  0.89us  154:  0.89us
 155:  0.89us  156:  0.89us  157:  0.89us  158:  0.89us  159:  0.89us
 160:  0.89us  161:  0.89us  162:  0.89us  163:  0.89us  164:  0.89us
 165:  0.89us  166:  0.89us  167:  0.89us  168:  0.89us  169:  0.89us
 170:  0.89us  171:  0.89us  172:  0.89us  173:  0.89us  174:  0.89us
 175:  0.89us  176:  0.89us  177:  0.89us  178:  0.89us  179:  0.89us
 180:  0.89us  181:  0.89us  182:  0.89us  183:  0.89us  184:  0.89us
 185:  0.89us  186:  0.89us  187:  0.89us  188:  0.89us  189:  0.89us
 190:  0.89us  191:  0.89us  192:  0.89us  193: 45.00us  194:  0.89us
 195:  0.89us  196:  0.89us  197:  0.89us  198:  0.89us  199:  0.89us
 200:  0.89us  201:  0.89us  202:  0.89us  203:  0.89us  204:  0.89us
 205:  0.89us  206:  0.89us  207:  0.89us  208:  0.89us  209:  0.89us
 210:  0.89us  211:  0.89us  212:  0.89us  213:  0.89us  214:  0.89us
 215:  0.89us  216:  0.89us  217:  0.89us  218:  0.89us  219:  0.89us
 220:  0.89us  221:  0.89us  222:  0.89us  223:  0.89us  224:  0.89us
 225:  0.89us  226:  0.89us  227:  0.89us  228:  0.89us  229:  0.89us
 230:  0.89us  231:  0.89us  232:  0.89us  233:  0.89us  234:  0.89us
 235:  0.89us  236:  0.89us  237:  0.89us  238:  0.89us  239:  0.89us
 240:  0.89us  241:  0.89us  242:  0.89us  243:  0.89us  244:  0.89us
 245:  0.89us  246:  0.89us  247:  0.89us  248:  0.89us  249:  0.89us
 250:  0.89us  251:  0.89us  252:  0.89us  253:  0.89us  254:  0.89us
 255:  0.89us  256:  0.89us  257: 45.53us  258:  0.89us  259:  0.89us
 260:  0.89us  261:  0.89us  262:  0.89us  263:  0.89us  264:  0.89us
 265:  0.89us  266:  0.89us  267:  0.89us  268:  0.89us  269:  0.89us
 270:  0.89us  271:  0.89us  272:  0.89us  273:  0.89us  274:  0.89us
 275:  0.89us  276:  0.89us  277:  0.89us  278:  0.89us  279:  0.89us
 280:  0.89us  281:  0.89us  282:  0.89us  283:  0.89us  284:  0.89us
 285:  0.89us  286:  0.89us  287:  0.89us  288:  0.89us  289:  0.89us
 290:  0.89us  291:  0.89us  292:  0.89us  293:  0.89us  294:  0.89us
 295:  0.89us  296:  0.89us  297:  0.89us  298:  0.89us  299:  0.89us
 300:  0.89us  301:  0.89us  302:  0.89us  303:  0.89us  304:  0.89us
 305:  0.89us  306:  0.89us  307:  0.89us  308:  0.89us  309:  0.89us
 310:  0.89us  311:  0.89us  312:  0.89us  313:  0.89us  314:  0.89us
 315:  0.89us  316:  0.89us  317:  0.89us  318:  0.89us  319:  0.89us
 320:  0.89us  321:  0.89us  322: 45.02us  323:  0.89us  324:  0.89us
 325:  0.89us  326:  0.89us  327:  0.89us  328:  0.89us  329:  0.89us
 330:  0.89us  331:  0.89us  332:  0.89us  333:  0.89us  334:  0.89us
 335:  0.89us  336:  0.89us  337:  0.89us  338:  0.89us  339:  0.89us
 340:  0.89us  341:  0.89us  342:  0.89us  343:  0.89us  344:  0.89us
 345:  0.89us  346:  0.89us  347:  0.89us  348:  0.89us  349:  0.89us
 350:  0.89us  351:  0.89us  352:  0.89us  353:  0.89us  354:  0.89us
 355:  0.89us  356:  0.89us  357:  0.89us  358:  0.89us  359:  0.89us
 360:  0.89us  361:  0.89us  362:  0.89us  363:  0.89us  364:  0.89us
 365:  0.89us  366:  0.89us  367:  0.89us  368:  0.89us  369:  0.89us
 370:  0.89us  371:  0.89us  372:  0.89us  373:  0.89us  374:  0.89us
 375:  0.89us  376:  0.89us  377:  0.89us  378:  0.89us  379:  0.89us
 380:  0.89us  381:  0.89us  382:  0.89us  383:  0.89us  384:  0.89us
 385:  0.89us  386: 45.56us  387:  0.89us  388:  0.89us  389:  0.89us
 390:  0.89us  391:  0.89us  392:  0.89us  393:  0.89us  394:  0.89us
 395:  0.89us  396:  0.89us  397:  0.89us  398:  0.89us  399:  0.89us

Perhaps what you are seeing is due to something other than SED e.g. memory corruption? You are using some relatively unusual functions (return of list to host, method parameter to kernel,...) and this could tickle some compiler bugs.

@jbqubit
Copy link
Contributor Author

jbqubit commented Nov 7, 2022

My example was indeed unnecessarily complex. I can reproduce the odd delays at n*64 without using the unusual functions. The delay on the line marked # D0 strongly influences the unusual behavior.

from artiq.experiment import *

class Delays(EnvExperiment):

	def build(self):
    	self.setattr_device("core")
    	self.setattr_device("ttl7")
    	self.ttl = self.ttl7

	def report(self, delays):
    	for i, d in enumerate(delays):
        	print("{:4d}:{:>6.2f}us".format(i, d/1000), end=" " if i % 5 != 4 else "\n")

	@kernel
	def run(self):
    	count = 200
    	delays = [0]*count
    	self.core.reset()
    	for i in range(count):
        	delay(1000*us)  # D0
        	t1 = self.core.get_rtio_counter_mu()
        	self.ttl.pulse(1*us)
        	t2 = self.core.get_rtio_counter_mu()
        	delays[i] = t2-t1
    	self.report(delays)
$ artiq_run repository/core_device_process_durations_sb0.py
   0:  3.98us	1:  1.22us	2:  0.81us	3:  0.78us	4:  0.78us
   5:  0.78us	6:  0.79us	7:  0.78us	8:  0.78us	9:  0.78us
  10:  0.79us   11:  0.78us   12:  0.78us   13:  0.78us   14:  0.79us
  15:  0.78us   16:  0.78us   17:  0.79us   18:  0.78us   19:  0.78us
  20:  0.79us   21:  0.78us   22:  0.78us   23:  0.79us   24:  0.78us
  25:  0.79us   26:  0.78us   27:  0.78us   28:  0.78us   29:  0.79us
  30:  0.78us   31:  0.78us   32:  0.79us   33:  0.78us   34:  0.78us
  35:  0.78us   36:  0.79us   37:  0.78us   38:  0.78us   39:  0.78us
  40:  0.78us   41:  0.78us   42:  0.78us   43:  0.79us   44:  0.78us
  45:  0.78us   46:  0.78us   47:  0.79us   48:  0.78us   49:  0.78us
  50:  0.79us   51:  0.78us   52:  0.78us   53:  0.78us   54:  0.79us
  55:  0.78us   56:  0.79us   57:  0.78us   58:  0.79us   59:  0.78us
  60:  0.78us   61:  0.78us   62:  0.78us   63:  0.78us   64:1033.01us
  65:  0.78us   66:  0.78us   67:  0.78us   68:  0.79us   69:  0.78us
  70:  0.78us   71:  0.79us   72:  0.78us   73:  0.78us   74:  0.78us
  75:  0.79us   76:  0.78us   77:  0.78us   78:  0.78us   79:  0.78us
  80:  0.78us   81:  0.78us   82:  0.78us   83:  0.78us   84:  0.78us
  85:  0.79us   86:  0.78us   87:  0.78us   88:  0.78us   89:  0.78us
  90:  0.78us   91:  0.78us   92:  0.79us   93:  0.78us   94:  0.78us
  95:  0.78us   96:  0.78us   97:  0.78us   98:  0.78us   99:  0.78us
 100:  0.79us  101:  0.79us  102:  0.78us  103:  0.78us  104:  0.78us
 105:  0.79us  106:  0.78us  107:  0.78us  108:  0.79us  109:  0.78us
 110:  0.78us  111:  0.78us  112:  0.79us  113:  0.78us  114:  0.78us
 115:  0.78us  116:  0.79us  117:  0.78us  118:  0.78us  119:  0.79us
 120:  0.78us  121:  0.78us  122:  0.78us  123:  0.78us  124:  0.78us
 125:  0.78us  126:  0.79us  127:  0.78us  128:63976.59us  129:  0.78us
 130:  0.78us  131:  0.78us  132:  0.78us  133:  0.79us  134:  0.78us
 135:  0.78us  136:  0.78us  137:  0.79us  138:  0.78us  139:  0.78us
 140:  0.78us  141:  0.78us  142:  0.79us  143:  0.78us  144:  0.78us
 145:  0.78us  146:  0.79us  147:  0.78us  148:  0.78us  149:  0.78us
 150:  0.78us  151:  0.78us  152:  0.78us  153:  0.79us  154:  0.78us
 155:  0.78us  156:  0.79us  157:  0.78us  158:  0.78us  159:  0.78us
 160:  0.79us  161:  0.78us  162:  0.78us  163:  0.78us  164:  0.78us
 165:  0.78us  166:  0.78us  167:  0.78us  168:  0.78us  169:  0.78us
 170:  0.79us  171:  0.78us  172:  0.78us  173:  0.78us  174:  0.79us
 175:  0.78us  176:  0.78us  177:  0.78us  178:  0.79us  179:  0.78us
 180:  0.78us  181:  0.79us  182:  0.78us  183:  0.78us  184:  0.78us
 185:  0.79us  186:  0.78us  187:  0.78us  188:  0.78us  189:  0.78us
 190:  0.78us  191:  0.78us  192:  0.79us  193:64977.36us  194:  0.78us
 195:  0.78us  196:  0.78us  197:  0.78us  198:  0.79us  199:  0.78us

@sbourdeauducq
Copy link
Member

There is nothing obviously wrong here. An event needs to be dequeued to make space in the buffer, and this can only happen when its timestamp has been reached. The D0 delay is putting events further into the future and then the CPU needs to wait for the dequeuing and event execution to happen.

@jbqubit
Copy link
Contributor Author

jbqubit commented Nov 7, 2022

Yes, that makes sense for ~1 ms delay at rep 64. However, I don't understand the > 60 ms delays at 128 and 193.

@sbourdeauducq
Copy link
Member

sbourdeauducq commented Nov 7, 2022

The delay is inside the loop, so you are shifting the timestamps by 1ms at each iteration (pulse) - so a ~64ms delay is expected.

@sbourdeauducq
Copy link
Member

And the 1ms delay is simply the first D0 plus the slack added by core.reset() minus the CPU execution time until the buffer is full. The value also looks correct.

@jbqubit
Copy link
Contributor Author

jbqubit commented Nov 9, 2022

Let me try this again with an clearer example.

from artiq.experiment import *
import numpy as np

class CoreDeviceComputationDelaysJWB(EnvExperiment):
    
    kernel_invariants = {"ftw0", "asf0", 'std_delay'}

    def build(self):
        self.trials = 70
        self.setattr_device("core")
        self.setattr_device("ttl8")
        self.ttl = self.ttl8
        self.urukul_channel = self.get_device('urukul0_ch0')
        self.urukul_switch = self.get_device('ttl_urukul0_sw0')
        #self.zotino = self.get_device('zotino0')

        self.ftw0 = self.urukul_channel.frequency_to_ftw(100*MHz)
        self.asf0 = self.urukul_channel.amplitude_to_asf(0.85)
        self.std_delay = 1*us

    def prepare(self):
        self.rtios = np.full(self.trials, 0, dtype=np.int64)
        self.nows = np.full(self.trials, 0, dtype=np.int64)
        self.slack = np.full(self.trials, 0, dtype=np.int64)

    def print_results(self):
        sheader = "\n{:>3s}: {:>12s} {:>12s} {:>12s} {:>12s} {:>12s}\n".format(
            'rep', 'now','delta now', 'rtio', 'delta rtio', 'slack')
        s = sheader
        for i in range(self.trials-1):
            s += "{:3}: {:12,.0f} {:12,.0f} {:12,.0f} {:12,.0f} {:12,.0f}\n".format(
                i, 
                self.nows[i], self.nows[i]-self.nows[i+1],
                self.rtios[i], self.rtios[i]-self.rtios[i+1],
                self.slack[i]
            )
            if (i+1)%35 == 0:
                s += sheader
        print(s)

    def run(self):
        self.ktest()
        self.print_results()

    @kernel
    def ktest(self):
        self.core.reset()
        delay(-100*us)
        rtio0 = self.core.get_rtio_counter_mu()
        now0 = now_mu()
        for i in range(self.trials):
            self.ttl.pulse(1*us)
            delay(99*us)
            self.rtios[i] = self.core.get_rtio_counter_mu() - rtio0
            self.nows[i] = now_mu() - rtio0
            self.slack[i] = now_mu() - self.core.get_rtio_counter_mu()
$ artiq_run repository/core_device_process_durations_jwb.py 

rep:          now    delta now         rtio   delta rtio        slack
  0:      121,984     -100,000        7,080       -5,848      111,552
  1:      221,984     -100,000       12,928       -2,104      208,120
  2:      321,984     -100,000       15,032       -2,032      306,080
  3:      421,984     -100,000       17,064       -1,928      404,160
  4:      521,984     -100,000       18,992       -2,080      502,072
  5:      621,984     -100,000       21,072       -1,920      600,160
  6:      721,984     -100,000       22,992       -2,032      698,128
  7:      821,984     -100,000       25,024       -1,928      796,192
  8:      921,984     -100,000       26,952       -2,072      894,128
  9:    1,021,984     -100,000       29,024       -1,920      992,208
 10:    1,121,984     -100,000       30,944       -2,112    1,090,096
 11:    1,221,984     -100,000       33,056       -1,984    1,188,112
 12:    1,321,984     -100,000       35,040       -2,112    1,286,000
 13:    1,421,984     -100,000       37,152       -1,984    1,384,016
 14:    1,521,984     -100,000       39,136       -2,144    1,481,864
 15:    1,621,984     -100,000       41,280       -2,120    1,579,752
 16:    1,721,984     -100,000       43,400       -2,104    1,677,648
 17:    1,821,984     -100,000       45,504       -1,928    1,775,736
 18:    1,921,984     -100,000       47,432       -2,088    1,873,632
 19:    2,021,984     -100,000       49,520       -1,952    1,971,680
 20:    2,121,984     -100,000       51,472       -1,952    2,069,728
 21:    2,221,984     -100,000       53,424       -1,928    2,167,792
 22:    2,321,984     -100,000       55,352       -1,952    2,265,848
 23:    2,421,984     -100,000       57,304       -2,040    2,363,808
 24:    2,521,984     -100,000       59,344       -2,200    2,461,608
 25:    2,621,984     -100,000       61,544       -1,936    2,559,664
 26:    2,721,984     -100,000       63,480       -2,448    2,657,224
 27:    2,821,984     -100,000       65,928       -1,936    2,755,288
 28:    2,921,984     -100,000       67,864       -2,080    2,853,200
 29:    3,021,984     -100,000       69,944       -2,008    2,951,280
 30:    3,121,984     -100,000       71,952       -2,008    3,049,184
 31:    3,221,984     -100,000       73,960       -1,952    3,147,240
 32:    3,321,984     -100,000       75,912       -1,968    3,245,264
 33:    3,421,984     -100,000       77,880       -1,944    3,343,328
 34:    3,521,984     -100,000       79,824       -1,944    3,441,384

rep:          now    delta now         rtio   delta rtio        slack
 35:    3,621,984     -100,000       81,768       -1,960    3,539,432
 36:    3,721,984     -100,000       83,728       -1,920    3,637,496
 37:    3,821,984     -100,000       85,648       -2,280    3,735,224
 38:    3,921,984     -100,000       87,928       -2,128    3,833,264
 39:    4,021,984     -100,000       90,056       -1,944    3,931,152
 40:    4,121,984     -100,000       92,000       -2,064    4,029,088
 41:    4,221,984     -100,000       94,064       -1,920    4,127,160
 42:    4,321,984     -100,000       95,984       -1,920    4,225,248
 43:    4,421,984     -100,000       97,904       -1,912    4,323,328
 44:    4,521,984     -100,000       99,816       -1,976    4,421,352
 45:    4,621,984     -100,000      101,792       -1,928    4,519,432
 46:    4,721,984     -100,000      103,720       -1,944    4,617,488
 47:    4,821,984     -100,000      105,664       -1,920    4,715,560
 48:    4,921,984     -100,000      107,584       -1,960    4,813,600
 49:    5,021,984     -100,000      109,544       -1,944    4,911,664
 50:    5,121,984     -100,000      111,488       -1,936    5,009,728
 51:    5,221,984     -100,000      113,424       -1,920    5,107,800
 52:    5,321,984     -100,000      115,344       -2,184    5,205,624
 53:    5,421,984     -100,000      117,528       -1,920    5,303,696
 54:    5,521,984     -100,000      119,448       -1,928    5,401,776
 55:    5,621,984     -100,000      121,376       -1,936    5,499,840
 56:    5,721,984     -100,000      123,312       -1,960    5,597,880
 57:    5,821,984     -100,000      125,272       -1,920    5,695,952
 58:    5,921,984     -100,000      127,192       -1,920    5,794,040
 59:    6,021,984     -100,000      129,112       -1,920    5,892,112
 60:    6,121,984     -100,000      131,032       -1,920    5,990,200
 61:    6,221,984     -100,000      132,952       -1,928    6,088,264
 62:    6,321,984     -100,000      134,880       -2,016    6,186,256
 63:    6,421,984     -100,000      136,896       -1,920    6,284,328
 64:    6,521,984     -100,000      138,816       -1,944    6,382,384
 65:    6,621,984     -100,000      140,760      -83,864    6,480,472
 66:    6,721,984     -100,000      224,624       -1,984    6,496,536
 67:    6,821,984     -100,000      226,608       -1,944    6,594,592
 68:    6,921,984     -100,000      228,552       -1,936    6,692,664

The default Kasli DIO FIFO depth is 128. Each pulse requires two FIFO slots (on and off). Here's where what I observe first breaks my expectation.

  • Rep 65 blocks on scheduling ttl.pulse(1*us) -- this makes sense since the FIFO is full until after wall time 221,640.
  • Rep 66 should block on scheduling ttl.pulse(1*us) until the wall time passes 321,984. This is because the FIFO is full until after 321,984.

I don't see how reps 66-68 can be scheduled with DRTIO.... the FIFO is full.

@sbourdeauducq
Copy link
Member

sbourdeauducq commented Nov 9, 2022

self.urukul_channel = self.get_device('urukul0_ch0')
#self.zotino = self.get_device('zotino0')

    self.ftw0 = self.urukul_channel.frequency_to_ftw(100*MHz)
    self.asf0 = self.urukul_channel.amplitude_to_asf(0.85)

This definitely not making it clearer. Can you also remove all other superfluous code and superfluous output? I do not understand what the problem is.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants