pothosware / SoapyAirspy

Soapy SDR plugin for the Airspy
https://github.com/pothosware/SoapyAirspy/wiki
MIT License
25 stars 13 forks source link

Reading speed & errors #10

Open dgorissen opened 7 years ago

dgorissen commented 7 years ago

First of all thanks for the effort on this, its been very useful for me so far. I have run into a performance issue I didn't think would be a problem.

Im using this through the Soapy python bindings. I have a specific use cases where I need to capture ~2.5 seconds of samples at a time in a continuous loop at a fixed centre frequency. Im running an airspy R2 operating at 2.5 msps.

I found out quickly that capturing ~2.5 seconds in one go causes errors or hangs, even on a relatively recent core i5. So I redid the code so I read the ~2.5 seconds in chunks.

That then makes the computer happy but occasionally it still prints out a 'O' to standard output which, from looking at the SoapyAirspy code means the client can not keep up. Im not sure what exactly happens internally at that point but its occasional enough not to bother me too much (can I avoid it though?).

However, I am now running the same code on a less powerful machine. Now very frequently it will fail to read a chunk with return error code -4. It should, however, be able to keep up. I have done similar tests with (py)rtlsdr.

So hence this issue. Am I approaching this in the correct way (see code below)? Is there an optimal buffer/chunk size I should be using? Should I activate/deactivate the stream on every 2.5s instead of only once at the beginning/end?

Code (stripped to its essentials) below. It runs in its own dedicated process.

rx_stream = sdr.setupStream(SOAPY_SDR_RX, SOAPY_SDR_CF32)
sdr.activateStream(_rx_stream)

nb = 65536
buff = numpy.zeros(nb, dtype=numpy.complex64)
niter = int(math.ceil(samples_per_scan / nb))

while True:
    samples = numpy.zeros(niter*nb, dtype=numpy.complex64)
    for i in range(niter):
         sr = sdr.readStream(rx_stream, [buff], nb)
         samples[i*nb:i*nb+nb] = buff

sdr.deactivateStream(rx_stream)
sdr.closeStream(rx_stream)
guruofquality commented 7 years ago

There is basically a little ring buffer in between the USB thread and the caller of readStream. So -4 should is SOAPY_SDR_OVERFLOW, where basically the ring buffer filled up, it didnt get read fast enough.

The optimal chunk size per readStream is going to be sdr.getStreamMTU(readStream) since thats a complete USB frame. Anything smaller will lead to fragmentation. Anything larger is ok, but it will just return the MTU size. Note that readStream() returns the number of samples read, which isnt necessary going to be nb (could be smaller). So its possible to just allocate a large buffer and always pass the available number of samples left to read. In this case the readStream is always as big as possible - MTU for this implementation.

Since this is python, perhaps its just too much going into and out of context switching is the problem. It might be worth a try to modify readStream() to fill the entire remaining buffer until timeout by calling aquireReadBuffer() and converting a loop. Then you could do one giant read without no loop required in python: https://github.com/pothosware/SoapyAirspy/blob/master/Streaming.cpp#L208

I'm suggesting that as an experiment, but if that turns out to be the problem, this loop is something we can add to the python wrapper for all devices.

Should I activate/deactivate the stream on every 2.5s instead of only once at the beginning/end?

That basically stops or starts the usb thread internally. I would leave the stream active so long as the application is interested in continuous streaming.

dgorissen commented 7 years ago

@guruofquality big thanks for this. I tweaked the code some more, switched to the MTU size and now things seem a bit better. However Im still getting way too many overflows (at 2.5 msps) to be useful. The process is literally doing nothing but pulling from the airspy and pushing into a multiprocessing queue (dropping if full). The fact that I also occasionally get the overflows (also at 2.5) on my desktop machine makes me suspect its the python context switching. I also tried my rtlsdr again at 2msps using pyrtlsdr and that seemed fine on both machines.

I dont quite fully get what you mean but will have a look at the C code and see if I can get something going. Upstream changes would be cool though :p

guruofquality commented 7 years ago

@dgorissen Since the overflow detection is happening between the receive thread and the caller, I'm positive that the issue is related to the SoapyAirspy implementation and/or python, but it shouldn’t have anything to do with airspy itself. I have this streaming_work branch I did a few things, I'm wondering if you can verify some things:

1) I noticed that the ring buffer wasnt allowing simultaneous reads and writes. I reimplemented it with atomics and only using condition variable to block when its actually empty. It doesnt sound like this should have made any difference since keeping up with a few msps should be easy. Curious if it makes a difference though

2) If you call readStream() with a very large buffer, what value does it return? I'm trying to confirm if getStreamMTU() is reporting accurately the size of the USB transfers. It looks like in the code they get resized to the actual value from the airspy API callback, so it might be under-reporting.

3) I was thinking of adding that loop to exhaust the receive buffer. This will mitigate the context switches (if you are willing to test). I just want to confirm that my changes so far dont break anything, and that the problem persists. Thanks!

dgorissen commented 7 years ago

@guruofquality this is great! Unfortunately Im traveling and wont be able to test until later this week but I definitely will and feed back here (also happy to test your INT / data format change).

As a small note on (2), this is what I tried the very first time. Allocate a big buffer, ~4m samples, and do one call of readStream(). On my i5 3ghz that would just hang. Then I switched to the loop I posted above and experimented with various buffer sizes. After your reply I switched to getStreamMTU() as the buffer size (1024 in my case) but I have not tried again with giving a bigger buffer. Will do.

dgorissen commented 7 years ago

@guruofquality ok, tested this. Removed the pkgs installed via apt, cloned/compiled/installed from source. Verified everything worked as before with the master branch, which it did (regular -4 errors). MTU size is returned as 2048.

Switched to the streaming branch and reran the same code. I see ~11-13 calls to readStream (as part of filling up my big buffer) and then it just hangs, nothing else seems to happen. No CPU usage or anything,

Tried CS16 as a dataformat, seemed to work but same behavior. Verified that switching to and from master all gives consistent behavior. Thoughts?

Edit: note this is on an ARM (Odroid XU4)

guruofquality commented 7 years ago

@dgorissen Sounds like I broke it on the stream branch. I didnt have an airspy to test on, but these are nearly identical changes that worked on rtl codebase.

Locking up though: Is the readStream call never retuning after timeout? There is a condition variable with a timeout here, so I wouldnt expect lockup: https://github.com/pothosware/SoapyAirspy/blob/streaming_work/Streaming.cpp#L300

... Its that or maybe you loop is just seeing timeout or zero return value and continuing to run the loop. This could mean that I messed up the buffer accounting, or the conversion between bytes vs samples, something like that.

The only thing I can suggest is printing in acquireReadBuffer, releaseReadBuffer, and readStream to see whats going on. I'm happy to look at a bunch of prints to see whats going on. Sorry for the trouble!

dgorissen commented 7 years ago

Thanks Josh. I added some printf's to readStream. See output here:

INFO - Detecting SDR devices...
INFO - found device: {device_id=0, driver=airspy, label=AIRSPY [644064dc:232b84cd], serial=644064dc:232b84cd}
INFO - Using driver: airspy
[INFO] Using format CS16.
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=0
  bufferedElems was zero, calling acquireReadBuffer with timeoutUs=100000 timeNs=0
enter acquireReadBuffer
_rx_callback
_rx_callback _buf_head=0, numBuffers=0
exit acquireReadBuffer, returning 65536
  acquireReadBuffer returned ret=65536
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=63488 flags=0
readstream exit bufferedElems=63488 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=63488
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=61440 flags=0
readstream exit bufferedElems=61440 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=61440
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=59392 flags=0
readstream exit bufferedElems=59392 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=59392
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=57344 flags=0
readstream exit bufferedElems=57344 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=57344
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=55296 flags=0
readstream exit bufferedElems=55296 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=55296
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=53248 flags=0
readstream exit bufferedElems=53248 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=53248
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=51200 flags=0
readstream exit bufferedElems=51200 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=51200
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=49152 flags=0
readstream exit bufferedElems=49152 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=49152
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=47104 flags=0
readstream exit bufferedElems=47104 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=47104
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=45056 flags=0
readstream exit bufferedElems=45056 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=45056
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=43008 flags=0
readstream exit bufferedElems=43008 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=43008
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=40960 flags=0
readstream exit bufferedElems=40960 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=40960
 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4

This is where it hangs, nothing else happens after that (this line in the code).

My python client code (fluff removed):

        # create a re-usable buffer for receiving samples
        nb = self._sdr.getStreamMTU(self._rx_stream)
        self.log.debug("Stream MTU set to %d" % nb)
        buff = numpy.zeros(nb, dtype=numpy.complex64)

        while exit_flag is None or not exit_flag.is_set():
            try:
                samples = numpy.zeros(self.samples_per_scan, dtype=numpy.complex64)
                num_left = self.samples_per_scan

                while num_left >= nb:
                    print("reading stream..")
                    sr = self._sdr.readStream(self._rx_stream, [buff], nb)

                    if sr.ret > 0:
                        nfail = max(0, nfail - 1)
                        i = self.samples_per_scan - num_left
                        samples[i:i+sr.ret] = buff[:sr.ret]
                        num_left -= sr.ret
                    elif sr.ret < 0:
                        self.log.warning("Failed to read samples, error code: %s" % (sr.ret))
                    else:
                        raise IOError("Return code 0, sdr disconnected")

Samples per scan is: 4194304

guruofquality commented 7 years ago

readstream enter readStream before bufferedElems if. bufferedElems=40960 going to convert into users buff0, buff0=0x1b2da08 returnedElems=2048 bytesPerSample=4

Thats really strange, its not even fetching more buffers, its still converting chunks from the first acquisition. I can only think of some kind of memory boundary issue.

dgorissen commented 7 years ago

Thanks. Updated the code and switched to CF32 but still the same problem. Just faster :) I will try narrow it down to a short bit of python code and try to replicate with rtlsdr.

INFO - found device: {device_id=0, driver=airspy, label=AIRSPY [644064dc:232b84cd], serial=644064dc:232b84cd}
INFO - Using driver: airspy
[INFO] Using format CF32.
('Samples per scan:', 4194304)
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=0
  bufferedElems was zero, calling acquireReadBuffer with timeoutUs=100000 timeNs=0
enter acquireReadBuffer
_rx_callback
_rx_callback _buf_head=0, numBuffers=0
exit acquireReadBuffer, returning 65536
  acquireReadBuffer returned ret=65536
 going to convert into users buff0, buff0=0x1bad0f8 _currentBuff=0xb3500470 returnedElems=8192 bytesPerSample=8
 converted into users buff0
 variables bumped for next call bufferedElems=57344 flags=0
readstream exit bufferedElems=57344 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=57344
 going to convert into users buff0, buff0=0x1bad0f8 _currentBuff=0xb3540470 returnedElems=8192 bytesPerSample=8
 converted into users buff0
 variables bumped for next call bufferedElems=49152 flags=0
readstream exit bufferedElems=49152 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=49152
 going to convert into users buff0, buff0=0x1bad0f8 _currentBuff=0xb3580470 returnedElems=8192 bytesPerSample=8
 converted into users buff0
 variables bumped for next call bufferedElems=40960 flags=0
readstream exit bufferedElems=40960 flags=32
reading stream..
readstream enter
 readStream before bufferedElems if. bufferedElems=40960
 going to convert into users buff0, buff0=0x1bad0f8 _currentBuff=0xb35c0470 returnedElems=8192 bytesPerSample=8
dgorissen commented 7 years ago

A bit more progress. I used the following self contained test script:

from __future__ import division
import time
import SoapySDR
from SoapySDR import *
import numpy
import math

results = SoapySDR.Device.enumerate()
args = results[0]

print("Using driver: %s" % args["driver"])
sdr = SoapySDR.Device(args)

sdr.setSampleRate(SOAPY_SDR_RX, 0, 2.5e6)
sdr.setFrequency(SOAPY_SDR_RX, 0, 'RF', 150000000)

# set the gains
sdr.setGain(SOAPY_SDR_RX, 0, 'IF', 5)
sdr.setGain(SOAPY_SDR_RX, 0, 'LNA', 5)
sdr.setGain(SOAPY_SDR_RX, 0, 'MIX', 5)

# enable bias-tee
sdr.writeSetting("biastee", "true")

rx_stream = sdr.setupStream(SOAPY_SDR_RX, SOAPY_SDR_CF32)
sdr.activateStream(rx_stream)

# create a re-usable buffer for receiving samples
nb = sdr.getStreamMTU(rx_stream)
buff = numpy.zeros(nb, dtype=numpy.complex64)
samples_per_scan = 4194304

print("Stream MTU set to %d" % nb)
print("Samples per scan:", samples_per_scan)

samples = numpy.zeros(samples_per_scan, dtype=numpy.complex64)
num_left = samples_per_scan

while num_left >= nb:
    print("reading batch from stream, num_left is ", num_left)
    sr = sdr.readStream(rx_stream, [buff], nb)

    print("flags ", sr.flags)
    print("time ns ", sr.timeNs)

    if sr.ret > 0:
        i = samples_per_scan - num_left
        samples[i:i+sr.ret] = buff[:sr.ret]
        num_left -= sr.ret
    else:
        print("Failed to read samples, error code: %s (nfail: %d/%d)" % (sr.ret, nfail, max_fail))
        break

sdr.deactivateStream(rx_stream)
sdr.closeStream(rx_stream)

Installed/compiled the rtlsdr module for soapy from source and ran the above script. Works fine.

Tried exactly the same script on the master branch of soapy airspy. Works fine.

Switched to the streaming_work branch:

dgorissen@odroid:~$ python soapytest.py 
Using driver: airspy
[INFO] Using format CF32.
Stream MTU set to 8192
('Samples per scan:', 4194304)
('reading batch from stream, num_left is ', 4194304)
readstream enter
 readStream before bufferedElems if. bufferedElems=0
  bufferedElems was zero, calling acquireReadBuffer with timeoutUs=100000 timeNs=0
enter acquireReadBuffer
_rx_callback
_rx_callback _buf_head=0, numBuffers=0
exit acquireReadBuffer, returning 65536
  acquireReadBuffer returned ret=65536
 going to convert into users buff0, buff0=0xc4f368 _currentBuff=0xb1d00470 returnedElems=8192 bytesPerSample=8
 converted into users buff0
 variables bumped for next call bufferedElems=57344 flags=0
readstream exit bufferedElems=57344 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4186112)
readstream enter
 readStream before bufferedElems if. bufferedElems=57344
 going to convert into users buff0, buff0=0xc4f368 _currentBuff=0xb1d40470 returnedElems=8192 bytesPerSample=8
 converted into users buff0
 variables bumped for next call bufferedElems=49152 flags=0
readstream exit bufferedElems=49152 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4177920)
readstream enter
 readStream before bufferedElems if. bufferedElems=49152
 going to convert into users buff0, buff0=0xc4f368 _currentBuff=0xb1d80470 returnedElems=8192 bytesPerSample=8
 converted into users buff0
 variables bumped for next call bufferedElems=40960 flags=0
readstream exit bufferedElems=40960 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4169728)
readstream enter
 readStream before bufferedElems if. bufferedElems=40960
 going to convert into users buff0, buff0=0xc4f368 _currentBuff=0xb1dc0470 returnedElems=8192 bytesPerSample=8
Segmentation fault

Mm, thats interesting, a segfault. Running in gdb gives:

(gdb) cont
Continuing.
[New Thread 0xb5941470 (LWP 7343)]
[Thread 0xb5941470 (LWP 7343) exited]
[New Thread 0xb5941470 (LWP 7344)]
[Thread 0xb5941470 (LWP 7344) exited]
Using driver: airspy
[New Thread 0xb5941470 (LWP 7345)]
[Thread 0xb5941470 (LWP 7345) exited]
[New Thread 0xb5941470 (LWP 7346)]
[INFO] Using format CF32.
[New Thread 0xb50c0470 (LWP 7347)]
[New Thread 0xb48c0470 (LWP 7348)]
Stream MTU set to 8192
('Samples per scan:', 4194304)
('reading batch from stream, num_left is ', 4194304)
readstream enter
 readStream before bufferedElems if. bufferedElems=0
  bufferedElems was zero, calling acquireReadBuffer with timeoutUs=100000 timeNs=0
enter acquireReadBuffer
_rx_callback
_rx_callback _buf_head=0, numBuffers=0
exit acquireReadBuffer, returning 65536
  acquireReadBuffer returned ret=65536
 going to convert into users buff0, buff0=0xc53ad8 _currentBuff=0xb1d00470 returnedElems=8192 bytesPerSample=8
 converted into users buff0
 variables bumped for next call bufferedElems=57344 flags=0
readstream exit bufferedElems=57344 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4186112)
readstream enter
 readStream before bufferedElems if. bufferedElems=57344
 going to convert into users buff0, buff0=0xc53ad8 _currentBuff=0xb1d40470 returnedElems=8192 bytesPerSample=8
 converted into users buff0
 variables bumped for next call bufferedElems=49152 flags=0
readstream exit bufferedElems=49152 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4177920)
readstream enter
 readStream before bufferedElems if. bufferedElems=49152
 going to convert into users buff0, buff0=0xc53ad8 _currentBuff=0xb1d80470 returnedElems=8192 bytesPerSample=8
 converted into users buff0
 variables bumped for next call bufferedElems=40960 flags=0
readstream exit bufferedElems=40960 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4169728)
readstream enter
 readStream before bufferedElems if. bufferedElems=40960
 going to convert into users buff0, buff0=0xc53ad8 _currentBuff=0xb1dc0470 returnedElems=8192 bytesPerSample=8

Thread 1 "python" received signal SIGSEGV, Segmentation fault.
__memcpy_neon () at ../sysdeps/arm/armv7/multiarch/memcpy_impl.S:568
568 ../sysdeps/arm/armv7/multiarch/memcpy_impl.S: No such file or directory.
(gdb) bt
#0  __memcpy_neon () at ../sysdeps/arm/armv7/multiarch/memcpy_impl.S:568
#1  0xb5a43f94 in SoapyAirspy::readStream(SoapySDR::Stream*, void* const*, unsigned int, int&, long long&, long) () from /usr/local/lib/SoapySDR/modules0.6-dev/libairspySupport.so
#2  0xb6aa0222 in _wrap_Device_readStream__ () from /usr/local/lib/python2.7/dist-packages/_SoapySDR.so
#3  0x00067bb6 in call_function (oparg=<optimized out>, pp_stack=0xbefff6a8) at ../Python/ceval.c:4350
#4  PyEval_EvalFrameEx (
    f=f@entry=Frame 0xb6d817b0, for file /usr/local/lib/python2.7/dist-packages/SoapySDR.py, line 1563, in readStream__ (self=<Device(this=<SwigPyObject at remote 0xb59ee590>) at remote 0xb5a029b0>, stream=<SwigPyObject at remote 0xb59ee5c0>, buffs=[12925656], numElems=8192L, flags=0, timeoutUs=100000), throwflag=throwflag@entry=0) at ../Python/ceval.c:2987
#5  0x00067f7c in fast_function (nk=<optimized out>, na=<optimized out>, n=6, pp_stack=0xbefff780, func=<function at remote 0xb6b35bf0>) at ../Python/ceval.c:4435
#6  call_function (oparg=<optimized out>, pp_stack=0xbefff780) at ../Python/ceval.c:4370
#7  PyEval_EvalFrameEx (
    f=f@entry=Frame 0xb60b9c70, for file /usr/local/lib/python2.7/dist-packages/SoapySDR.py, line 1580, in readStream (self=<Device(this=<SwigPyObject at remote 0xb59ee590>) at remote 0xb5a029b0>, stream=<SwigPyObject at remote 0xb59ee5c0>, buffs=[<numpy.ndarray at remote 0xb5a0f958>], numElems=8192L, flags=0, timeoutUs=100000, b=<numpy.ndarray at remote 0xb5a0f958>, ptrs=[12925656]), throwflag=throwflag@entry=0) at ../Python/ceval.c:2987
#8  0x0006270e in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=4, kws=0xb6d6a438, kwcount=0, defs=0xb6d60e4c, 
    defcount=2, closure=0x0) at ../Python/ceval.c:3582
#9  0x00068054 in fast_function (nk=0, na=4, n=4, pp_stack=0xbefff8c8, func=<function at remote 0xb6b35d30>) at ../Python/ceval.c:4445
#10 call_function (oparg=<optimized out>, pp_stack=0xbefff8c8) at ../Python/ceval.c:4370
#11 PyEval_EvalFrameEx (f=f@entry=Frame 0xb6d6a2f0, for file soapytest.py, line 42, in <module> (), throwflag=throwflag@entry=0) at ../Python/ceval.c:2987
#12 0x0006270e in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=0, kws=0x0, kwcount=0, defs=0x0, defcount=0, 
    closure=0x0) at ../Python/ceval.c:3582
#13 0x00062560 in PyEval_EvalCode (co=<optimized out>, globals=<optimized out>, locals=<optimized out>) at ../Python/ceval.c:669
#14 0x000880d6 in run_mod.lto_priv.1999 (mod=<optimized out>, filename=<optimized out>, 
    globals={'SOAPY_SDR_END_BURST': 2, 'SOAPY_SDR_ONE_PACKET': 16, 'SOAPY_SDR_END_ABRUPT': 8, 'SOAPY_SDR_RX': 1, 'SOAPY_SDR_MORE_FRAGMENTS': 32, 'SOAPY_SDR_TX': 0, 'SOAPY_SDR_U16': 'U16', 'SOAPY_SDR_F32': 'F32', 'SOAPY_SDR_U32': 'U32', 'SOAPY_SDR_CF32': 'CF32', 'SOAPY_SDR_CORRUPTION': -3, 'num_left': 4169728, 'SOAPY_SDR_U8': 'U8', 'sr': <StreamResult(this=<SwigPyObject at remote 0xb59ee5d8>) at remote 0xb5a02a10>, 'SOAPY_SDR_F64': 'F64', 'SOAPY_SDR_S8': 'S8', 'SOAPY_SDR_UNDERFLOW': -7, 'SOAPY_SDR_OVERFLOW': -4, '__package__': None, 'SOAPY_SDR_CS8': 'CS8', 'SOAPY_SDR_CU12': 'CU12', 'SOAPY_SDR_CU32': 'CU32', 'SOAPY_SDR_TIME_ERROR': -6, 'SOAPY_SDR_CU16': 'CU16', 'SOAPY_SDR_WAIT_TRIGGER': 64, 'SoapySDR': <module at remote 0xb6a48230>, 'numpy': <module at remote 0xb6b1fe90>, '__doc__': None, 'math': <module at remote 0xb69e52b0>, 'buff': <numpy.ndarray at remote 0xb5a0f958>, 'division': <_Feature(mandatory=(3, 0, 0, 'alpha', 0), optional=(2, 2, 0, 'alpha', 2), compiler_flag=8192) at remote 0xb6b1bc38>, 'SOAPY_SDR_CS4': 'CS4',...(truncated), 
    locals={'SOAPY_SDR_END_BURST': 2, 'SOAPY_SDR_ONE_PACKET': 16, 'SOAPY_SDR_END_ABRUPT': 8, 'SOAPY_SDR_RX': 1, 'SOAPY_SDR_MORE_FRAGMENTS': 32, 'SOAPY_SDR_TX': 0, 'SOAPY_SDR_U16': 'U16', 'SOAPY_SDR_F32': 'F32', 'SOAPY_SDR_U32': 'U32', 'SOAPY_SDR_CF32': 'CF32', 'SOAPY_SDR_CORRUPTION': -3, 'num_left': 4169728, 'SOAPY_SDR_U8': 'U8', 'sr': <StreamResult(this=<SwigPyObject at remote 0xb59ee5d8>) at remote 0xb5a02a10>, 'SOAPY_SDR_F64': 'F64', 'SOAPY_SDR_S8': 'S8', 'SOAPY_SDR_UNDERFLOW': -7, 'SOAPY_SDR_OVERFLOW': -4, '__package__': None, 'SOAPY_SDR_CS8': 'CS8', 'SOAPY_SDR_CU12': 'CU12', 'SOAPY_SDR_CU32': 'CU32', 'SOAPY_SDR_TIME_ERROR': -6, 'SOAPY_SDR_CU16': 'CU16', 'SOAPY_SDR_WAIT_TRIGGER': 64, 'SoapySDR': <module at remote 0xb6a48230>, 'numpy': <module at remote 0xb6b1fe90>, '__doc__': None, 'math': <module at remote 0xb69e52b0>, 'buff': <numpy.ndarray at remote 0xb5a0f958>, 'division': <_Feature(mandatory=(3, 0, 0, 'alpha', 0), optional=(2, 2, 0, 'alpha', 2), compiler_flag=8192) at remote 0xb6b1bc38>, 'SOAPY_SDR_CS4': 'CS4',...(truncated), flags=0xbefffa74, arena=0x2ecc38) at ../Python/pythonrun.c:1376
#15 0x00083ffc in PyRun_FileExFlags (fp=0x2b4738, filename=0xbefffd8a "soapytest.py", start=<optimized out>, 
    globals={'SOAPY_SDR_END_BURST': 2, 'SOAPY_SDR_ONE_PACKET': 16, 'SOAPY_SDR_END_ABRUPT': 8, 'SOAPY_SDR_RX': 1, 'SOAPY_SDR_MORE_FRAGMENTS': 32, 'SOAPY_SDR_TX': 0, 'SOAPY_SDR_U16': 'U16', 'SOAPY_SDR_F32': 'F32', 'SOAPY_SDR_U32': 'U32', 'SOAPY_SDR_CF32': 'CF32', 'SOAPY_SDR_CORRUPTION': -3, 'num_left': 4169728, 'SOAPY_SDR_U8': 'U8', 'sr': <StreamResult(this=<SwigPyObject at remote 0xb59ee5d8>) at remote 0xb5a02a10>, 'SOAPY_SDR_F64': 'F64', 'SOAPY_SDR_S8': 'S8', 'SOAPY_SDR_UNDERFLOW': -7, 'SOAPY_SDR_OVERFLOW': -4, '__package__': None, 'SOAPY_SDR_CS8': 'CS8', 'SOAPY_SDR_CU12': 'CU12', 'SOAPY_SDR_CU32': 'CU32', 'SOAPY_SDR_TIME_ERROR': -6, 'SOAPY_SDR_CU16': 'CU16', 'SOAPY_SDR_WAIT_TRIGGER': 64, 'SoapySDR': <module at remote 0xb6a48230>, 'numpy': <module at remote 0xb6b1fe---Type <return> to continue, or q <return> to quit---
90>, '__doc__': None, 'math': <module at remote 0xb69e52b0>, 'buff': <numpy.ndarray at remote 0xb5a0f958>, 'division': <_Feature(mandatory=(3, 0, 0, 'alpha', 0), optional=(2, 2, 0, 'alpha', 2), compiler_flag=8192) at remote 0xb6b1bc38>, 'SOAPY_SDR_CS4': 'CS4',...(truncated), 
    locals={'SOAPY_SDR_END_BURST': 2, 'SOAPY_SDR_ONE_PACKET': 16, 'SOAPY_SDR_END_ABRUPT': 8, 'SOAPY_SDR_RX': 1, 'SOAPY_SDR_MORE_FRAGMENTS': 32, 'SOAPY_SDR_TX': 0, 'SOAPY_SDR_U16': 'U16', 'SOAPY_SDR_F32': 'F32', 'SOAPY_SDR_U32': 'U32', 'SOAPY_SDR_CF32': 'CF32', 'SOAPY_SDR_CORRUPTION': -3, 'num_left': 4169728, 'SOAPY_SDR_U8': 'U8', 'sr': <StreamResult(this=<SwigPyObject at remote 0xb59ee5d8>) at remote 0xb5a02a10>, 'SOAPY_SDR_F64': 'F64', 'SOAPY_SDR_S8': 'S8', 'SOAPY_SDR_UNDERFLOW': -7, 'SOAPY_SDR_OVERFLOW': -4, '__package__': None, 'SOAPY_SDR_CS8': 'CS8', 'SOAPY_SDR_CU12': 'CU12', 'SOAPY_SDR_CU32': 'CU32', 'SOAPY_SDR_TIME_ERROR': -6, 'SOAPY_SDR_CU16': 'CU16', 'SOAPY_SDR_WAIT_TRIGGER': 64, 'SoapySDR': <module at remote 0xb6a48230>, 'numpy': <module at remote 0xb6b1fe90>, '__doc__': None, 'math': <module at remote 0xb69e52b0>, 'buff': <numpy.ndarray at remote 0xb5a0f958>, 'division': <_Feature(mandatory=(3, 0, 0, 'alpha', 0), optional=(2, 2, 0, 'alpha', 2), compiler_flag=8192) at remote 0xb6b1bc38>, 'SOAPY_SDR_CS4': 'CS4',...(truncated), closeit=1, flags=0xbefffa74) at ../Python/pythonrun.c:1362
#16 0x00082bf6 in PyRun_SimpleFileExFlags (fp=0x2b4738, filename=0xbefffd8a "soapytest.py", closeit=1, flags=0xbefffa74) at ../Python/pythonrun.c:948
#17 0x000421e6 in Py_Main (argc=<optimized out>, argv=<optimized out>) at ../Modules/main.c:640
#18 0xb6ec28aa in __libc_start_main (main=0x41d01 <main>, argc=2, argv=0xbefffc64, init=<optimized out>, fini=0x157985 <__libc_csu_fini>, rtld_fini=0xb6fe2b89 <_dl_fini>, stack_end=0xbefffc64)
    at libc-start.c:291
#19 0x00041c3c in _start ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) py-bt
Traceback (most recent call first):
  File "/usr/local/lib/python2.7/dist-packages/SoapySDR.py", line 1563, in readStream__
    return _SoapySDR.Device_readStream__(self, stream, buffs, numElems, flags, timeoutUs)
  File "/usr/local/lib/python2.7/dist-packages/SoapySDR.py", line 1580, in readStream
    return self.readStream__(stream, ptrs, numElems, flags, timeoutUs)
  File "soapytest.py", line 42, in <module>
    sr = sdr.readStream(rx_stream, [buff], nb)
(gdb) 

Same if I use CS16 / numpy.int16. Hope this helps.

guruofquality commented 7 years ago

@dgorissen I think I found it, _currentBuff was float* not char*, so the pointer math was bad. Try again with the latest branch. I think it will work now.

dgorissen commented 7 years ago

Almost :)

(gdb) cont
Continuing.
[New Thread 0xb5941470 (LWP 2101)]
[Thread 0xb5941470 (LWP 2101) exited]
[New Thread 0xb5941470 (LWP 2102)]
[Thread 0xb5941470 (LWP 2102) exited]
Using driver: airspy
[New Thread 0xb5941470 (LWP 2103)]
[Thread 0xb5941470 (LWP 2103) exited]
[New Thread 0xb5941470 (LWP 2104)]
[INFO] Using format CS16.
[New Thread 0xb50c0470 (LWP 2105)]
[New Thread 0xb48c0470 (LWP 2106)]
Stream MTU set to 16384
('Samples per scan:', 4194304)
('reading batch from stream, num_left is ', 4194304)
readstream enter
 readStream before bufferedElems if. bufferedElems=0
  bufferedElems was zero, calling acquireReadBuffer with timeoutUs=100000 timeNs=0
enter acquireReadBuffer
_rx_callback
_rx_callback _buf_head=0, numBuffers=0
exit acquireReadBuffer, returning 65536
  acquireReadBuffer returned ret=65536
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1d00470 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=49152 flags=0
readstream exit bufferedElems=49152 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4177920)
readstream enter
 readStream before bufferedElems if. bufferedElems=49152
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1d10470 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=32768 flags=0
readstream exit bufferedElems=32768 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4161536)
readstream enter
 readStream before bufferedElems if. bufferedElems=32768
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1d20470 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=16384 flags=0
readstream exit bufferedElems=16384 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4145152)
readstream enter
 readStream before bufferedElems if. bufferedElems=16384
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1d30470 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=0 flags=0
 releasing read buffer
readstream exit bufferedElems=0 flags=0
('flags ', 0)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4128768)
readstream enter
 readStream before bufferedElems if. bufferedElems=0
  bufferedElems was zero, calling acquireReadBuffer with timeoutUs=100000 timeNs=0
enter acquireReadBuffer
_rx_callback
_rx_callback _buf_head=1, numBuffers=1
exit acquireReadBuffer, returning 65536
  acquireReadBuffer returned ret=65536
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1d40478 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=49152 flags=0
readstream exit bufferedElems=49152 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4112384)
readstream enter
 readStream before bufferedElems if. bufferedElems=49152
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1d50478 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=32768 flags=0
readstream exit bufferedElems=32768 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4096000)
readstream enter
 readStream before bufferedElems if. bufferedElems=32768
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1d60478 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=16384 flags=0
readstream exit bufferedElems=16384 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4079616)
readstream enter
 readStream before bufferedElems if. bufferedElems=16384
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1d70478 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=0 flags=0
 releasing read buffer
readstream exit bufferedElems=0 flags=0
('flags ', 0)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4063232)
readstream enter
 readStream before bufferedElems if. bufferedElems=0
  bufferedElems was zero, calling acquireReadBuffer with timeoutUs=100000 timeNs=0
enter acquireReadBuffer
_rx_callback
_rx_callback _buf_head=2, numBuffers=2
exit acquireReadBuffer, returning 65536
  acquireReadBuffer returned ret=65536
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1d80480 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=49152 flags=0
readstream exit bufferedElems=49152 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4046848)
readstream enter
 readStream before bufferedElems if. bufferedElems=49152
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1d90480 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=32768 flags=0
readstream exit bufferedElems=32768 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4030464)
readstream enter
 readStream before bufferedElems if. bufferedElems=32768
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1da0480 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=16384 flags=0
readstream exit bufferedElems=16384 flags=32
('flags ', 32)
('time ns ', 0L)
('reading batch from stream, num_left is ', 4014080)
readstream enter
 readStream before bufferedElems if. bufferedElems=16384
 going to convert into users buff0, buff0=0xc4f3c0 _currentBuff=0xb1db0480 returnedElems=16384 bytesPerSample=4
 converted into users buff0
 variables bumped for next call bufferedElems=0 flags=0
 releasing read buffer
readstream exit bufferedElems=0 flags=0
('flags ', 0)
('time ns ', 0L)
('reading batch from stream, num_left is ', 3997696)
readstream enter
 readStream before bufferedElems if. bufferedElems=0
  bufferedElems was zero, calling acquireReadBuffer with timeoutUs=100000 timeNs=0
enter acquireReadBuffer
_rx_callback
_rx_callback _buf_head=3, numBuffers=3
*** Error in `/usr/bin/python': double free or corruption (out): 0x00bff398 ***

Thread 6 "python" received signal SIGABRT, Aborted.
[Switching to Thread 0xb50c0470 (LWP 2105)]
__libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
47  ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S: No such file or directory.
(gdb) bt
#0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
#1  0xb6ed0638 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#2  0xb6ed133a in __GI_abort () at abort.c:89
#3  0xb6ef752a in __libc_message (do_abort=do_abort@entry=2, fmt=0xb6f77eec "*** Error in `%s': %s: 0x%s ***\n")
    at ../sysdeps/posix/libc_fatal.c:175
#4  0xb6efb4a6 in malloc_printerr (action=<optimized out>, str=0xb6f77fe4 "double free or corruption (out)", ptr=<optimized out>, 
    ar_ptr=<optimized out>) at malloc.c:5007
#5  0xb6efbbd4 in _int_free (av=0xb6f9479c <main_arena>, p=<optimized out>, have_lock=<optimized out>) at malloc.c:3868
#6  0xb5a43bca in _rx_callback(airspy_transfer_t*) () from /usr/local/lib/SoapySDR/modules0.6-dev/libairspySupport.so
#7  0xb59cbbd8 in ?? () from /usr/lib/arm-linux-gnueabihf/libairspy.so.0
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) py-bt
Traceback (most recent call first):
guruofquality commented 7 years ago

I cant make sense of this. The only reason I can think of for the malloc error in the _rx_callback is that the buffer is resized to match the transfer size in ::rx_callback: buff.resize(t->sample_count * bytesPerSample);

dgorissen commented 7 years ago

Thanks again. A really odd one yes. Output below. Any other tools I can use to help you figure this out let me know. I will also have a think.

Worth asking the airspy folk?

Stream MTU set to 65536
('Samples per scan:', 4194304)
('reading batch from stream, num_left is ', 4194304)
readstream enter
 readStream before bufferedElems if. bufferedElems=0
  bufferedElems was zero, calling acquireReadBuffer with timeoutUs=100000 timeNs=0
enter acquireReadBuffer
_rx_callback
_rx_callback _buf_head=0, numBuffers=0
rx_callback sample_count=65536
exit acquireReadBuffer, returning 65536
  acquireReadBuffer returned ret=65536
 going to convert into users buff0, buff0=0xddde08 _currentBuff=0xbdddc8 returnedElems=65536 bytesPerSample=4

Thread 1 "python" received signal SIGSEGV, Segmentation fault.
0xb6f079b8 in __memcpy_neon () at ../sysdeps/arm/armv7/multiarch/memcpy_impl.S:590
590 ../sysdeps/arm/armv7/multiarch/memcpy_impl.S: No such file or directory.
(gdb) bt
#0  0xb6f079b8 in __memcpy_neon () at ../sysdeps/arm/armv7/multiarch/memcpy_impl.S:590
#1  0xb5a43f94 in SoapyAirspy::readStream(SoapySDR::Stream*, void* const*, unsigned int, int&, long long&, long) ()
   from /usr/local/lib/SoapySDR/modules0.6-dev/libairspySupport.so
#2  0xb6aa0222 in _wrap_Device_readStream__ () from /usr/local/lib/python2.7/dist-packages/_SoapySDR.so
#3  0x00067bb6 in call_function (oparg=<optimized out>, pp_stack=0xbefff6a8) at ../Python/ceval.c:4350
#4  PyEval_EvalFrameEx (
    f=f@entry=Frame 0xb6d817b0, for file /usr/local/lib/python2.7/dist-packages/SoapySDR.py, line 1563, in readStream__ (self=<Device(this=<SwigPyObject at remote 0xb59ee590>) at remote 0xb5a029b0>, stream=<SwigPyObject at remote 0xb59ee5c0>, buffs=[14540296], numElems=65536L, flags=0, timeoutUs=100000), throwflag=throwflag@entry=0)
    at ../Python/ceval.c:2987
#5  0x00067f7c in fast_function (nk=<optimized out>, na=<optimized out>, n=6, pp_stack=0xbefff780, func=<function at remote 0xb6b35bf0>) at ../Python/ceval.c:4435
#6  call_function (oparg=<optimized out>, pp_stack=0xbefff780) at ../Python/ceval.c:4370
#7  PyEval_EvalFrameEx (
    f=f@entry=Frame 0xb60b9c70, for file /usr/local/lib/python2.7/dist-packages/SoapySDR.py, line 1580, in readStream (self=<Device(this=<SwigPyObject at remote 0xb59ee590>) at remote 0xb5a029b0>, stream=<SwigPyObject at remote 0xb59ee5c0>, buffs=[<numpy.ndarray at remote 0xb5a0f958>], numElems=65536L, flags=0, timeoutUs=100000, b=<numpy.ndarray at remote 0xb5a0f958>, ptrs=[14540296]), throwflag=throwflag@entry=0) at ../Python/ceval.c:2987
#8  0x0006270e in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=4, kws=0xb6d6a438, kwcount=0, 
    defs=0xb6d60e4c, defcount=2, closure=0x0) at ../Python/ceval.c:3582
#9  0x00068054 in fast_function (nk=0, na=4, n=4, pp_stack=0xbefff8c8, func=<function at remote 0xb6b35d30>) at ../Python/ceval.c:4445
#10 call_function (oparg=<optimized out>, pp_stack=0xbefff8c8) at ../Python/ceval.c:4370
#11 PyEval_EvalFrameEx (f=f@entry=Frame 0xb6d6a2f0, for file soapytest.py, line 42, in <module> (), throwflag=throwflag@entry=0) at ../Python/ceval.c:2987
#12 0x0006270e in PyEval_EvalCodeEx (co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=0, kws=0x0, kwcount=0, defs=0x0, 
    defcount=0, closure=0x0) at ../Python/ceval.c:3582
#13 0x00062560 in PyEval_EvalCode (co=<optimized out>, globals=<optimized out>, locals=<optimized out>) at ../Python/ceval.c:669
#14 0x000880d6 in run_mod.lto_priv.1999 (mod=<optimized out>, filename=<optimized out>, 
    globals={'SOAPY_SDR_END_BURST': 2, 'SOAPY_SDR_ONE_PACKET': 16, 'SOAPY_SDR_END_ABRUPT': 8, 'SOAPY_SDR_RX': 1, 'SOAPY_SDR_MORE_FRAGMENTS': 32, 'SOAPY_SDR_TX': 0, 'SOAPY_SDR_U16': 'U16', 'SOAPY_SDR_F32': 'F32', 'SOAPY_SDR_U32': 'U32', 'SOAPY_SDR_CF32': 'CF32', 'SOAPY_SDR_CORRUPTION': -3, 'num_left': 4194304, 'SOAPY_SDR_U8': 'U8', 'SOAPY_SDR_F64': 'F64', 'SOAPY_SDR_S8': 'S8', 'SOAPY_SDR_UNDERFLOW': -7, 'SOAPY_SDR_OVERFLOW': -4, '__package__': None, 'SOAPY_SDR_CS8': 'CS8', 'SOAPY_SDR_CU12': 'CU12', 'SOAPY_SDR_CU32': 'CU32', 'SOAPY_SDR_TIME_ERROR': -6, 'SOAPY_SDR_CU16': 'CU16', 'SOAPY_SDR_WAIT_TRIGGER': 64, 'SoapySDR': <module at remote 0xb6a46250>, 'numpy': <module at remote 0xb6b1feb0>, '__doc__': None, 'math': <module at remote 0xb69e52b0>, 'buff': <numpy.ndarray at remote 0xb5a0f958>, 'division': <_Feature(mandatory=(3, 0, 0, 'alpha', 0), optional=(2, 2, 0, 'alpha', 2), compiler_flag=8192) at remote 0xb6b1bc38>, 'SOAPY_SDR_CS4': 'CS4', 'samples': <numpy.ndarray at remote 0xb5a0f980>, '__warningregistry__': {("Not impor...(truncated), 
    locals={'SOAPY_SDR_END_BURST': 2, 'SOAPY_SDR_ONE_PACKET': 16, 'SOAPY_SDR_END_ABRUPT': 8, 'SOAPY_SDR_RX': 1, 'SOAPY_SDR_MORE_FRAGMENTS': 32, 'SOAPY_SDR_TX': 0, 'SOAPY_SDR_U16': 'U16', 'SOAPY_SDR_F32': 'F32', 'SOAPY_SDR_U32': 'U32', 'SOAPY_SDR_CF32': 'CF32', 'SOAPY_SDR_CORRUPTION': -3, 'num_left': 4194304, 'SOAPY_SDR_U8': 'U8', 'SOAPY_SDR_F64': 'F64', 'SOAPY_SDR_S8': 'S8', 'SOAPY_SDR_UNDERFLOW': -7, 'SOAPY_SDR_OVERFLOW': -4, '__package__': None, 'SOAPY_SDR_CS8': 'CS8', 'SOAPY_SDR_CU12': 'CU12', 'SOAPY_SDR_CU32': 'CU32', 'SOAPY_SDR_TIME_ERROR': -6, 'SOAPY_SDR_CU16': 'CU16', 'SOAPY_SDR_WAIT_TRIGGER': 64, 'SoapySDR': <module at remote 0xb6a46250>, 'numpy': <module at remote 0xb6b1feb0>, '__doc__': None, 'math': <module at remote 0xb69e52b0>, 'buff': <numpy.ndarray at remote 0xb5a0f958>, 'division': <_Feature(mandatory=(3, 0, 0, 'alpha', 0), optional=(2, 2, 0, 'alpha', 2), compiler_flag=8192) at remote 0xb6b1bc38>, 'SOAPY_SDR_CS4': 'CS4', 'samples': <numpy.ndarray at remote 0xb5a0f980>, '__warningregistry__': {("Not impor...(truncated), 
    flags=0xbefffa74, arena=0x2ecc38) at ../Python/pythonrun.c:1376
#15 0x00083ffc in PyRun_FileExFlags (fp=0x2b4738, filename=0xbefffd8a "soapytest.py", start=<optimized out>, 
    globals={'SOAPY_SDR_END_BURST': 2, 'SOAPY_SDR_ONE_PACKET': 16, 'SOAPY_SDR_END_ABRUPT': 8, 'SOAPY_SDR_RX': 1, 'SOAPY_SDR_MORE_FRAGMENTS': 32, 'SOAPY_SDR_TX': 0, 'SOAPY_SDR_U16': 'U16', 'SOAPY_SDR_F32': 'F32', 'SOAPY_SDR_U32': 'U32', 'SOAPY_SDR_CF32': 'CF32', 'SOAPY_SDR_CORRUPTION': -3, 'num_left': 4194304, 'SOAPY_SDR_U8': 'U8', 'SOAPY_SDR_F64': 'F64', 'SOAPY_SDR_S8': 'S8', 'SOAPY_SDR_UNDERFLOW': -7, 'SOAPY_SDR_OVERFLOW': -4, '__package__': None, 'SOAPY_SDR_CS8': 'CS8', 'SOAPY_SDR_CU12': 'CU12', 'SOAPY_SDR_CU32': 'CU32', 'SOAPY_SDR_TIME_ERROR': -6, 'SOAPY_SDR_CU16': 'CU16', 'SOAPY_SDR_WAIT_TRIGGER': 64, 'SoapySDR': <module at remote 0xb6a46250>, 'numpy': <module at remote 0xb6b1feb0>, '__doc__': None, 'math': <module at remote 0xb69e52b0>, 'buff': <numpy.ndarray at remote 0xb5a0f958>, 'division': <_Feature(mandatory=(3, 0, 0, 'alpha', 0), optional=(2, 2, 0, 'alpha', 2), compiler_flag=8192) at remote 0xb6b1bc38>, 'SOAPY_SDR_CS4': 'CS4', 'samples': <numpy.ndarray at remote 0xb5a0f980>, '__warningregistry__': {("Not impor...(truncated), 
    locals={'SOAPY_SDR_END_BURST': 2, 'SOAPY_SDR_ONE_PACKET': 16, 'SOAPY_SDR_END_ABRUPT': 8, 'SOAPY_SDR_RX': 1, 'SOAPY_SDR_MORE_FRAGMENTS': 32, 'SOAPY_SDR_TX': 0, 'SOAPY_SDR_U16': 'U16', 'SOAPY_SDR_F32': 'F32', 'SOAPY_SDR_U32': 'U32', 'SOAPY_SDR_CF32': 'CF32', 'SOAPY_SDR_CORRUPTION': -3, 'num_left': 4194304, 'SOAPY_SDR_U8': 'U8', 'SOAPY_SDR_F64': 'F64', 'SOAPY_SDR_S8': 'S8', 'SOAPY_SDR_UNDERFLOW': -7, 'SOAPY_SDR_OVERFLOW': -4, '__package__': None, 'SOAPY_SDR_CS8': 'CS8', 'SOAPY_SDR_CU12': 'CU12', 'SOAPY_SDR_CU32': 'CU32', 'SOAPY_SDR_TIME_ERROR': -6, 'SOAPY_SDR_CU16': 'CU16', 'SOAPY_SDR_WAIT_TRIGGER': 64, 'SoapySDR': <module at remote 0xb6a46250>, 'numpy': <module at remote 0xb6b1feb0>, '__doc__': None, ---Type <return> to continue, or q <return> to quit---
'math': <module at remote 0xb69e52b0>, 'buff': <numpy.ndarray at remote 0xb5a0f958>, 'division': <_Feature(mandatory=(3, 0, 0, 'alpha', 0), optional=(2, 2, 0, 'alpha', 2), compiler_flag=8192) at remote 0xb6b1bc38>, 'SOAPY_SDR_CS4': 'CS4', 'samples': <numpy.ndarray at remote 0xb5a0f980>, '__warningregistry__': {("Not impor...(truncated), closeit=1, 
    flags=0xbefffa74) at ../Python/pythonrun.c:1362
#16 0x00082bf6 in PyRun_SimpleFileExFlags (fp=0x2b4738, filename=0xbefffd8a "soapytest.py", closeit=1, flags=0xbefffa74) at ../Python/pythonrun.c:948
#17 0x000421e6 in Py_Main (argc=<optimized out>, argv=<optimized out>) at ../Modules/main.c:640
#18 0xb6ec28aa in __libc_start_main (main=0x41d01 <main>, argc=2, argv=0xbefffc64, init=<optimized out>, fini=0x157985 <__libc_csu_fini>, rtld_fini=0xb6fe2b89 <_dl_fini>, 
    stack_end=0xbefffc64) at libc-start.c:291
#19 0x00041c3c in _start ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
guruofquality commented 7 years ago

going to convert into users buff0, buff0=0xddde08 _currentBuff=0xbdddc8 returnedElems=65536 bytesPerSample=4 0xb6f079b8 in __memcpy_neon () at ../sysdeps/arm/armv7/multiarch/memcpy_impl.S:590

1 0xb5a43f94 in SoapyAirspy::readStream(SoapySDR::Stream, void const*, unsigned int, int&, long long&, long) ()

It just dies in the memcpy. The copy is larger than the previous one because of the MTU fix. Is there any reason to suspect that the numpy buffer is smaller than bytesPerSample=4 * 65536? I believe that the source buffer is correctly returnedElems * bytesPerSample in size.

dgorissen commented 7 years ago

Found it...

Some point along my testing I had switched from SOAPY_SDR_CF32/numpy.complex64 to SOAPY_SDR_CF16/numpy.int16 and was seeing the same segfaults so thought it did not matter. But that turned out to be wrong. After your latest fixes, switching back to CF32/complex64 worked as expected... sorry for that :( Thanks for your patience and at least some other bugs were squashed in the process. As an aside what is the correct python type to use alongside CF16?

So to finally continue our original thread.. My original code now runs with your streaming_work branch. The -4 errors are less than before but I still get at least one batch of 65536 samples failing for every capture period (~1.5 seconds). Any further suggestions?

guruofquality commented 7 years ago

Cool, glad its working. Sounds like it can be merged since this branch offers a few improvements.

As an aside what is the correct python type to use alongside CF16?

I forget the syntax, but since there are no complex in types, you simply need to use a 2 dimensional type of numpy.int16, so that each sample is an array of two int16 elements.

My original code now runs with your streaming_work branch. The -4 errors are less than before but I still get at least one batch of 65536 samples failing for every capture period (~1.5 seconds). Any further suggestions?

I didnt realize that this was an arm device before. I don't ultimately know what rate can be sustained.

On the python end, you can save the extra numpy operation by reading directly into the numpy buffer:

numSamplesRead = 0
samples = np.zeros(numSamplesRequested, dtype=...)
while numSamplesRead < numSamplesRequested:
    sr = sdr.readStream(rx_stream,
        [samples[numSamplesRead:]],
        numSamplesRequested-numSamplesRead)
    numSamplesRead += sr.ret

This deserves another open issue, but on the C end, libairspy has a usb ring buffer 0) filled by libusb, which it 1) copies/converts/+some dsp into an internal ring buffer which passed to the caller. In SoapyAirspy, we 2) copy this into another ring buffer, and then readSamples once again 3) copies it into the user's provided memory. This is basically insane; FWIW, gr-osmosdr does this exact implementation for several of the USB based devices, and its usually low sample rate and not a big deal for x86 machines. I really wished all of these USB driver libraries directly exposed the libusb ring buffer handles somehow, since SoapySDR has an API exactly for this.

In any case, what I wanted to experiment with was skipping 2 and 3 by letting SoapyAirspy::aquireReadBuffer() actually wait for the libusb/airspy rx_callback, and then block it with a condition, acquiring access to the buffer for readSamples. And then SoapyAirspy::releaseReadBuffer() would allow the rx_callback to unblock and return.

Its sort of like having a ring buffer of size 1 and relying on the underlying airspy library and libusb to handle any buffering or overflow. I'm very curious if something like this helps the current issue on the odroid or is a better or simpler way with less copies to work with async/callback based libraries like this. Feel free to try this suggestion without me, otherwise, when I get some time I will try it out on soapy rtl and airspy, until then, use the numpy suggestion (good to save an extra copy), and it looks like I will merge this stream work into master.

dgorissen commented 7 years ago

Thanks Josh. Made the suggested changes.

Note that this shows a less powerful odroid (the C2) working with the airspy at 10msps. Hence I would think my UX4 should have no issue with 2.5msps

I also tried my code with a more powerful Intel Atom x5. That is better than the UX4 but also drops occasionally. I also recall the dropping happening with my desktop core i5 on the master branch. However, can't test at the moment though as the HD has died. Will resurrect though. I will take a look at your suggestion but I feel is probably going to be more reliable if you are able to make a patch.

Also, just to give you a sense what Im aiming for. Im working on v2.0 of this.

dgorissen commented 7 years ago

Did you manage to have a poke at this? After some thought I thought it might be easier if I just write a very thin python wrapper around the airspy host tools directly, avoiding all overhead.

guruofquality commented 7 years ago

Note that this shows a less powerful odroid (the C2) working with the airspy at 10msps. Hence I would think my UX4 should have no issue with 2.5msps

It might be the case that the overflows simply arent being reported in this case. Since the buffers are multiple of the FFT size this might not be noticed. You would have to check the terminal for "O" prints in this case.

Sort of a related question, but are the occasional drops/overflows actually harmful in this particular use case?

Did you manage to have a poke at this? After some thought I thought it might be easier if I just write a very thin python wrapper around the airspy host tools directly, avoiding all overhead.be tolerable.

The interesting/worthwhile thing would be to have the airspy async callback call a registered python function. Wrapping the async callback like that is as close as you can get to the library, as opposed to stashing the buffer for a streaming API to pick it up. No idea if thats a significant difference.

So I tested this on RTL and made the same changes to Airspy, you can try it out on this branch. It compiles but no idea if it works, its just a near identical change: https://github.com/pothosware/SoapyAirspy/tree/streaming_callback_handshake

I'm adding a rate testing option to SoapySDRUtil, I personally wanted this to test out streaming changes, but I think it would also be a good data point in this case as well (when I get it finished).

guruofquality commented 7 years ago

I'm adding a rate testing option to SoapySDRUtil, I personally wanted this to test out streaming changes, but I think it would also be a good data point in this case as well (when I get it finished).

On this branch, there is a rate test, looks like this for RTL: https://github.com/pothosware/SoapySDR/tree/rate_test

SoapySDRUtil --rate=2e6 --direction=RX
######################################################
## Soapy SDR -- the SDR abstraction library
######################################################

Detached kernel driver
Found Rafael Micro R820T tuner
Reattached kernel driver
Detached kernel driver
Found Rafael Micro R820T tuner
Exact sample rate is: 2000000.052982 Hz
[INFO] Using format CS8.
Stream format: CS8
Num channels: 1
Element size: 2 bytes
Begin RX rate test at 2 Msps
Starting stream loop, press Ctrl+C to exit...
1.99854 Msps    3.99707 Bps     Overflows 0
1.99929 Msps    3.99858 Bps     Overflows 0
dgorissen commented 7 years ago

Got back to testing. With current master and slightly updated hardware I can now read without overflow ('O's) it seems, so thats good. The odroid still gets overflows. Though in principle they arent problematic, when other processing processes kick in it does become worse and Id rather avoid them. However after some thought I decided to move away from the odroid for this and other reasons.

The streaming_callback_handshake branch consistently fails for me though with a -2 error. How best to debug this?

The streaming rate functionality in SoapySDRUtil is useful, thanks. I get consistently around 9.9 Bps for a 2.5e6 sample rate. I do notice that my output does not show the Overflows column you have in yours?

guruofquality commented 7 years ago

The streaming_callback_handshake branch consistently fails for me though with a -2 error. How best to debug this?

It was again something that i tested on rtl and tried to copy over. -2 is the stream error code (SOAPY_SDR_STREAM_ERROR), so probably a bad state. Theres only one place that returns that error code: https://github.com/pothosware/SoapyAirspy/blob/streaming_callback_handshake/Streaming.cpp#L275

Which would imply that the number of bytes wasnt reset to 0. activateStream() should handle this, as well as all calls to releaseReadBuffer() which is called by readStream(). So thats something to print, also check if your code is making the call to activateStream(). Just a guess...

The streaming rate functionality in SoapySDRUtil is useful, thanks. I get consistently around 9.9 Bps for a 2.5e6 sample rate. I do notice that my output does not show the Overflows column you have in yours?

I may have changed it since then to only print overflows when the count is > 0. If the util doesn't get overflows that may say something about the overhead of python vs C/C++.