Interesting observation regarding varying time duration it takes to execute fg.start() [a flowgraph

Hi,
I have an interesting observation to share, and I want to see if
anybody
can help me shed some light. When I measure time in python in the
following
way:

t1 = datetime.now()
self.start()
t2=datetime.now()
diff = t2.microsecond - t1.microsecond
print “Difference %d”, diff

I get very different time benchmarks…it goes from 309 microseconds
(minimum) to all the way 1 second(max). Do you know why this thread
spawning
is taking such a variety of time after flowgraph start()??
====Code Below=====
#!/usr/bin/env python

from gnuradio import gr, gru, modulation_utils
from gnuradio import usrp
from gnuradio.eng_option import eng_option
from gnuradio import eng_notation
from optparse import OptionParser
from datetime import datetime
import sys

class my_top_block(gr.top_block):
def init(self):
gr.top_block.init(self)
self.interp = 64
self.waveform_type = gr.GR_GAUSSIAN
self.waveform_ampl = 32000
self.waveform_freq = 2.5e9
self.waveform_offset = 0
self.nsamples = 0
self._instantiate_blocks ()
self.set_waveform_type (self.waveform_type)

def usb_freq (self):
    return self.u.dac_freq() / self.interp

def usb_throughput (self):
    return self.usb_freq () * 4

def set_waveform_type (self, type):
    self._configure_graph (type)
    self.waveform_type = type

def set_waveform_ampl (self, ampl):
    self.waveform_ampl = ampl
    self.siggen.set_amplitude (ampl)
    self.noisegen.set_amplitude (ampl)

def set_waveform_freq (self, freq):
    self.waveform_freq = freq
    self.siggen.set_frequency (freq)

def set_waveform_offset (self, offset):
    self.waveform_offset = offset
    self.siggen.set_offset (offset)

def set_interpolator (self, interp):
    self.interp = interp
    self.siggen.set_sampling_freq (self.usb_freq ())
    self.u.set_interp_rate (interp)

def _instantiate_blocks (self):
    self.src = None
    self.u = usrp.sink_c (0, self.interp)
    self.noisegen = gr.noise_source_c (gr.GR_GAUSSIAN,
                                       self.waveform_ampl)
    self.head = None
    if self.nsamples > 0:
        self.head = gr.head(gr.sizeof_gr_complex, 

int(self.nsamples))

def _configure_graph (self, type):
    try:
        self.lock()
        self.disconnect_all ()

        if self.head:
            self.connect(self.head, self.u)
            tail = self.head
        else:
            tail = self.u

        if type == gr.GR_UNIFORM or type == gr.GR_GAUSSIAN:
            self.connect (self.noisegen, tail)
            self.noisegen.set_type (type)
            self.src = self.noisegen
        else:
            raise ValueError, type
    finally:
        self.unlock()

def set_freq(self, target_freq):
    r = self.u.tune(self.subdev.which(),self.subdev,2.5e9)
    if r:
        #print "r.baseband_freq =",

eng_notation.num_to_str(r.baseband_freq)
#print “r.dxc_freq =”,
eng_notation.num_to_str(r.dxc_freq)
#print “r.residual_freq =”,
eng_notation.num_to_str(r.residual_freq)
#print “r.inverted =”, r.inverted
return True

    return False

def build_graph(self):
  demods = modulation_utils.type_1_demods()
  parser = OptionParser (option_class=eng_option)
  parser.add_option ("-T", "--tx-subdev-spec", type="subdev",

default=(0, 0),
help=“select USRP Tx side A or B”)
parser.add_option ("-f", “–rf-freq”, type=“eng_float”,
default=None,
help=“set RF center frequency to FREQ”)
parser.add_option ("-i", “–interp”, type=“int”, default=64,
help=“set fgpa interpolation rate to INTERP
[default=%default]”)
parser.add_option ("-d", “–decim”, type=“int”, default=32,
help=“set fgpa decimation rate to DECIM
[default=%default]”)
parser.add_option ("–sine", dest=“type”, action=“store_const”,
const=gr.GR_SIN_WAVE,
help=“generate a complex sinusoid [default]”,
default=gr.GR_SIN_WAVE)
parser.add_option ("–const", dest=“type”, action=“store_const”,
const=gr.GR_CONST_WAVE,
help=“generate a constant output”)
parser.add_option ("–gaussian", dest=“type”,
action=“store_const”,
const=gr.GR_GAUSSIAN,
help=“generate Gaussian random output”)
parser.add_option ("–uniform", dest=“type”, action=“store_const”,
const=gr.GR_UNIFORM,
help=“generate Uniform random output”)

  parser.add_option ("-w", "--waveform-freq", type="eng_float",

default=0,
help=“set waveform frequency to FREQ
[default=%default]”)
parser.add_option ("-a", “–amplitude”, type=“eng_float”,
default=16e3,
help=“set waveform amplitude to AMPLITUDE
[default=%default]”, metavar=“AMPL”)
parser.add_option ("-g", “–gain”, type=“eng_float”, default=None,
help=“set output gain to GAIN
[default=%default]”)
parser.add_option ("-o", “–offset”, type=“eng_float”, default=0,
help=“set waveform offset to OFFSET
[default=%default]”)
parser.add_option ("-N", “–nsamples”, type=“eng_float”,
default=0,
help=“set number of samples to transmit
[default=+inf]”)
(options, args) = parser.parse_args ()

  if len(args) != 0:
      parser.print_help()
      raise SystemExit

  if options.rf_freq is None:
      sys.stderr.write("usrp_siggen: must specify RF center 

frequency
with -f RF_FREQ\n")
parser.print_help()
raise SystemExit

  if options.tx_subdev_spec is None:
      options.tx_subdev_spec = usrp.pick_tx_subdevice(self.u)

  m = usrp.determine_tx_mux_value(self.u, options.tx_subdev_spec)
  print "mux = %#04x" % (m,)
  self.u.set_mux(m)
  self.subdev = usrp.selected_subdev(self.u, options.tx_subdev_spec)
  print "Using TX d'board %s" % (self.subdev.side_and_name(),)

  if options.gain is None:
      self.subdev.set_gain(self.subdev.gain_range()[1])    # set max 

Tx
gain
else:
self.subdev.set_gain(options.gain) # set max Tx gain

  if not self.set_freq(options.rf_freq):
      sys.stderr.write('Failed to set RF frequency\n')
      raise SystemExit

  self.subdev.set_enable(True)                       # enable

transmitter

  • def start_graph(self):
    t1 = datetime.now()
    self.start()
    t2 = datetime.now()
    diff = t2.microsecond - t1.microsecond
    print “Time it takes to start the flowgraph%d” % diff*
def stop_graph(self):
  self.subdev.set_enable(False)
  self.stop()

On Sun, Mar 07, 2010 at 02:05:12PM -0500, Bishal T. wrote:

I get very different time benchmarks…it goes from 309 microseconds
(minimum) to all the way 1 second(max). Do you know why this thread spawning
is taking such a variety of time after flowgraph start()??

I seriously doubt it ever take 309us :slight_smile:

If you subtract two datetimes you get a timedelta.
See the docs.

t1 = datetime.now()
self.start()
t2=datetime.now()
delta = t2 - t1
print delta

Eric

Thank you for your reply Eric.
I did print delta and delta.microseconds and guess what I did get
this:

Receiver (0) = BABA0002
Requested RX Bitrate: 100k
Probe Level 39
0:00:00.000327 [This is from printing delta]
327 [This is from printing delta.microseconds]

Why do you think I should not get 309us? I am sorry if I don’t get
something
fundamental here. Thanks again for helping me out :slight_smile:

On Sun, Mar 07, 2010 at 04:07:58PM -0500, Bishal T. wrote:

fundamental here. Thanks again for helping me out :slight_smile:
No problem. 309us may be reasonable.

In general the wide variance that you’re seeeing could be caused by
pretty much any other activity on the machine. You are measuring
“wall time”.

Eric

Yes Matt, you were correct. Now the range between min-time recorded and
max-time recorded is much less. Min = 309us (still), Max = 2349us. So
range
~= 2ms.

I believe it is due to Eric’s reasoning, multiple services running on my
host machine, although I have to mention I am running these programs as
“sudo”. Anyways, I will try to run it on a different host with nothing
much
going on, and see if I can reduce the range variation of 2ms.

Thank you Eric and Matt for your time,
Sincerely,

On 03/07/2010 01:12 PM, Eric B. wrote:

Why do you think I should not get 309us? I am sorry if I don’t get something
fundamental here. Thanks again for helping me out :slight_smile:

No problem. 309us may be reasonable.

In general the wide variance that you’re seeeing could be caused by
pretty much any other activity on the machine. You are measuring
“wall time”.

Does this flowgraph have a USRP1? If so, the very long time could be
when you have first powered up the USRP1 and so it needs to have its
FPGA image downloaded.

Matt

On Mon, Mar 08, 2010 at 04:09:49PM -0500, Bishal T. wrote:

Yes Matt, you were correct. Now the range between min-time recorded and
max-time recorded is much less. Min = 309us (still), Max = 2349us. So range
~= 2ms.

I believe it is due to Eric’s reasoning, multiple services running on my
host machine, although I have to mention I am running these programs as
“sudo”.

Sudo doesn’t have anything (directly) to do with scheduling…

Eric