›

Logging time reduced when using Android SDK

VinayVinay
in Android

I have been using the Android SDK for connecting to a Metawear C. I am facing a problem while logging data. When I use the Metabase Android App, I am able to log nearly 295 seconds of data. At the same time, when I use the SDK to log data, I am initially establishing a connection with the board. After which I am starting to log data. When I stop the logging after around 5 minutes, I am many a times finding that the board logged data only for a minute or two.

Initially I thought that it was a problem because I was using "false" for overwrite. But even after replacing it with "true", I am finding the same issue.

One thing that I noted was, I can log for a longer time on my own app after I log using the Metabase app. Hence, another attempt at resolving the issue was to use logging.clearEntries(). That didnt help either. I am facing the same issue.

I am not sure what I am doing wrong. Clearly my implementation of using the logging sdk is wrong. Would really appreciate some help with best practices/sequence of events to log the data properly.

Comments

  • EricEric
    edited January 2019
    • What Android SDK version are you using?

    • What sensors are you using?

      • Whatever settings are they using?

    • Post relevant code snippets of your app.

  • VinayVinay

    What Android SDK version are you using?

    My Target Android SDK version is 28. Metawear SDK version is 3.6.2.

    What sensors are you using?

    I am only using the accelerometer.

    Whatever settings are they using?

    The frequency is 12.5 Hz and the ODR is 2g.

    • Post relevant code snippets of your app.

    I have 4 Buttons (connectButton, disconnectButton, startLogging and stopLogging) and 1 TextView (status)

    connectButton.setOnClickListener(new View.OnClickListener() {
    @Override
    public void onClick(View v) {
        Log.v("BUTTON", "Start");
        status.setText("Connecting to Device");
        board.connectAsync().continueWith(new Continuation<Void, Void>() {
            @Override
            public Void then(Task<Void> task) throws Exception {
                if (task.isFaulted()) {
                    status.setText("Failed to connect. Please make sure the device is closeby and has sufficient battery life.");
                    connectButton.setText("Retry");
                } else {
                    status.setText("Connected");
                }
                return null;
            }
        }, Task.UI_THREAD_EXECUTOR);
    }
});

disconnectButton.setOnClickListener(new View.OnClickListener() {
    @Override
    public void onClick(View v) {
        Log.v("BUTTON", "Stop");
        board.tearDown();
        status.setText("Disconnecting from Device");
        board.disconnectAsync().continueWith(new Continuation<Void, Void>() {
            @Override
            public Void then(Task<Void> task) throws Exception {
                status.setText("Disconnected");            
                return null;
            }
        }, Task.UI_THREAD_EXECUTOR);
    }
});

startLogging.setOnClickListener(new View.OnClickListener() {
    @Override
    public void onClick(View v) {
        startAccelerometerLogging();
    }
});

stopLogging.setOnClickListener(new View.OnClickListener() {
    @Override
    public void onClick(View v) {
        stopAccelerometerLogging();
    }
});

    void startAccelerometerLogging(){
    starttime = System.currentTimeMillis();
    logging = board.getModule(Logging.class);
    logging.start(true);
    if(accelerometer==null) {
        accelerometer = board.getModule(Accelerometer.class);
        accelerometer.configure()
                .odr(frequency)
                .range(odr)
                .commit();

        accelerometer.acceleration().addRouteAsync(new RouteBuilder() {
            @Override
            public void configure(RouteComponent source) {
                source.log(new Subscriber() {
                    @Override
                    public void apply(Data data, Object... env) {
                        Acceleration d = data.value(Acceleration.class);
                        long timestamp = data.timestamp().getTimeInMillis();
                        Log.v("Data ", "x : " + d.x() + " y : " + d.y() + " z : " + d.z() + " t : " + timestamp);
                    }
                });
            }
        }).continueWith(new Continuation<Route, Void>() {
            @Override
            public Void then(Task<Route> task) throws Exception {
                accelerometer.acceleration().start();
                accelerometer.start();
                return null;
            }
        });
    }
    else{
        accelerometer.acceleration().start();
        accelerometer.start();
    }
}

void stopAccelerometerLogging(){
    stoptime = System.currentTimeMillis();
    Log.v("stoptime", ""+stoptime);
    Log.v("ExpectedTotalTimeLogged", ""+((stoptime-starttime)/1000.0)+" seconds");
    if (accelerometer!=null){
        accelerometer.stop();
        accelerometer.acceleration().stop();
        logging.stop();

        logging.downloadAsync(100, new Logging.LogDownloadUpdateHandler() {
            @Override
            public void receivedUpdate(long nEntriesLeft, long totalEntries) {
                Log.i("MainActivity", "Progress Update = " + nEntriesLeft + "/" + totalEntries);
            }
        }).continueWithTask(new Continuation<Void, Task<Void>>() {
            @Override
            public Task<Void> then(Task<Void> task) throws Exception {
                if(task.isFaulted()){
                    Log.v("Error", "Download Failed");
                }
                else{
                    Log.v("Download", "Download Complete");
                    logging.clearEntries();
                }
                return null;
            }
        });
    }
}
  • VinayVinay

    I ran some tests and am posting my output below

    Log Iteration 1:-

    V/starttime: 1547537685358
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
W/RenderThread: type=1400 audit(0.0:88729): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
D/BluetoothAdapter: isLeEnabled(): ON
D/BluetoothLeScanner: could not find callback wrapper
W/RenderThread: type=1400 audit(0.0:88731): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.debug.egl.changepixelformat"
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
W/RenderThread: type=1400 audit(0.0:88732): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
D/DecorView: onWindowFocusChangedFromViewRoot hasFocus: true, DecorView@95b8feb[MetaWearCapture]
V/stoptime: 1547537798825
V/ExpectedTotalTimeLogged: 113.467 seconds
W/RenderThread: type=1400 audit(0.0:88734): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
V/Data :: x : 0.18969727 y : 0.2993164 z : 0.9727173 t : 1547537685988
V/Data :: x : 0.19122314 y : 0.30236816 z : 0.98101807 t : 1547537686069
V/Data :: x : 0.19042969 y : 0.30096436 z : 0.9793701 t : 1547537686149
.......
V/Data :: x : 0.19085693 y : 0.30065918 z : 0.9793701 t : 1547537798809
V/Data :: x : 0.19073486 y : 0.30078125 z : 0.9783325 t : 1547537798889
V/Download: Download Complete

    Received Logged data is for 112.901 s

    Log Iteration 2:-

    V/starttime: 1547538130593
W/RenderThread: type=1400 audit(0.0:88746): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
V/stoptime: 1547538192013
V/ExpectedTotalTimeLogged: 61.42 seconds
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
W/RenderThread: type=1400 audit(0.0:88747): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
V/Data :: x : 0.18963623 y : 0.2982788 z : 0.9730835 t : 1547538131065
V/Data :: x : 0.19177246 y : 0.30065918 z : 0.9812012 t : 1547538131144
V/Data :: x : 0.19104004 y : 0.30010986 z : 0.9789429 t : 1547538131224
V/Data :: x : 0.19085693 y : 0.3013916 z : 0.97924805 t : 1547538131305
.....
V/Data :: x : 0.1906128 y : 0.30059814 z : 0.98046875 t : 1547538191967
V/Data :: x : 0.19030762 y : 0.30059814 z : 0.9795532 t : 1547538192046
V/Download: Download Complete

    Received Logged data is for 60.981 s

    Log Iteration 3:-

    V/starttime: 1547538355827
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
W/RenderThread: type=1400 audit(0.0:88785): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
V/stoptime: 1547538394580
V/ExpectedTotalTimeLogged: 38.753 seconds
W/RenderThread: type=1400 audit(0.0:88787): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
V/Data :: x : 0.18908691 y : 0.29882812 z : 0.97265625 t : 1547538356284
V/Data :: x : 0.19134521 y : 0.30114746 z : 0.9810791 t : 1547538356365
V/Data :: x : 0.19055176 y : 0.30059814 z : 0.9790039 t : 1547538356444
V/Data :: x : 0.19146729 y : 0.30096436 z : 0.9796753 t : 1547538356525
V/Data :: x : 0.19134521 y : 0.30059814 z : 0.9790039 t : 1547538356605
V/Data :: x : 0.19055176 y : 0.30047607 z : 0.97943115 t : 1547538356684
.....
V/Data :: x : 0.190979 y : 0.2993164 z : 0.9801636 t : 1547538394502
V/Data :: x : 0.19085693 y : 0.29907227 z : 0.9796753 t : 1547538394583
V/Download: Download Complete

    Received Logged data is for 38.299s

    Log iteration 4:-

    V/starttime: 1547538482354
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
W/RenderThread: type=1400 audit(0.0:88805): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.debug.egl.changepixelformat"
W/RenderThread: type=1400 audit(0.0:88808): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
D/DecorView: onWindowFocusChangedFromViewRoot hasFocus: true, DecorView@95b8feb[MetaWearCapture]
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
W/RenderThread: type=1400 audit(0.0:88811): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
V/stoptime: 1547538602722
V/ExpectedTotalTimeLogged: 120.368 seconds
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
W/RenderThread: type=1400 audit(0.0:88813): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
V/Data :: x : 0.18945312 y : 0.2980957 z : 0.9724121 t : 1547538482848
V/Data :: x : 0.190979 y : 0.3008423 z : 0.98236084 t : 1547538482929
V/Data :: x : 0.19116211 y : 0.300354 z : 0.979187 t : 1547538483008
V/Data :: x : 0.19073486 y : 0.30041504 z : 0.97906494 t : 1547538483089
V/Data :: x : 0.19085693 y : 0.30065918 z : 0.97961426 t : 1547538483169
V/Data :: x : 0.19085693 y : 0.3005371 z : 0.9793091 t : 1547538483248
....
V/Data :: x : 0.19067383 y : 0.2999878 z : 0.9802246 t : 1547538566173
V/Data :: x : 0.190979 y : 0.29943848 z : 0.9802246 t : 1547538566254
V/Download: Download Complete

    Received Logged data is for 83.406s

    Log Iteration 5:-

    V/starttime: 1547538689779
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
W/RenderThread: type=1400 audit(0.0:88821): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
V/stoptime: 1547538737017
V/ExpectedTotalTimeLogged: 47.238 seconds
W/RenderThread: type=1400 audit(0.0:88822): avc: denied { read } for name="u:object_r:vendor_default_prop:s0" dev="tmpfs" ino=16952 scontext=u:r:untrusted_app:s0:c215,c256,c512,c768 tcontext=u:object_r:vendor_default_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.debug.egl.swapinterval"
V/Download: Download Complete

    Received Logged data is for 0.0s

  • VinayVinay
    edited January 2019

    I don't receive any data after the 4th iteration. The 4th iteration has a total cumulative logging time of 295 s. Which means that the flash memory is full at this time. But since I am using,

    logging.start(true);

    If I understood the documentation correctly, it should not matter anyway if the flash memory is full or not since the device is supposed to just overwrite the values with the latest readings from the accelerometer. Did I understand wrong?

    As soon as I log using the Metabase App and then log with my application, I am able to log data again.

    The device doesnt log data even if I remove the battery and reset the device. Which leads me to believe that the Metabase App uses some call that erases all the data saved on the flash when I choose to stop logging and download the data.

    Edit

    I tried the same with

    logging.start(false);

    and ran into the same problem.

    Another thing that I noticed is that, if I rerun my application by changing the boolean values in the function

    logging.start(boolean);

    the logging works and I can download the logged data. Which in the previous case happened only after I ran the Metabase App.

  • VinayVinay

    I don't mean to spam. I am just posting results from the experiments I am running to see if any of it can help identify where the problem is.

    I ran another experiment to see what happens if I log more than 5 minutes of data comparing both boolean values.

    Case : overwrite=false

    logging.start(false)

    V/starttime: 1547542681787
...
V/stoptime: 1547543043055
V/ExpectedTotalTimeLogged: 361.268 seconds
...
V/Data :: x : 0.02935791 y : -0.016906738 z : 1.0328369 t : 1547542682465
V/Data :: x : 0.02923584 y : -0.017089844 z : 1.0419312 t : 1547542682544
...
V/Data :: x : 0.028686523 y : -0.018371582 z : 1.0404663 t : 1547542982015
V/Download: Download Complete

    Difference between starttime and first reading from the log - 678 milliseconds
    This would be the time required for the android device to send the command and the Metawear device to start reading sensor values.

    Difference between endtime and last reading from the log - 61,040 milliseconds
    This indicates that as soon as the flash memory is full, the device stops taking readings.

    Conclusion: Works as expected. Any new values after the flash is full is discarded.

    Case : overwrite=true

    logging.start(true)

    V/starttime: 1547543250731
...
V/stoptime: 1547543595902
V/ExpectedTotalTimeLogged: 345.171 seconds
...
V/Data :: x : 0.02935791 y : -0.017028809 z : 1.0328369 t : 1547543251467
V/Data :: x : 0.029052734 y : -0.016479492 z : 1.0431519 t : 1547543251546
...
V/Data :: x : 0.038208008 y : -0.020996094 z : 1.039978 t : 1547543546242
V/Download: Download Complete

    Difference between starttime and first reading from the log - 736 milliseconds
    This would be the time required for the android device to send the command and the Metawear device to start reading sensor values.

    Difference between endtime and last reading from the log - 49,660 milliseconds
    This indicates that as soon as the flash memory is full, the device stops taking readings.

    Conclusion: Works the same as when overwrite is false? I expected a large difference between the starttime and the first reading indicating that whatever values the device logged initially would be deleted for the new values. Instead we got a large difference between the stoptime and the last logged timestamp.

    Should I post this as a different discussion? Since it may have nothing to do with the problem stated.

  • EricEric
    edited January 2019

    What are the specs of your board? Post a screen shot from the MetaBase diagnostic screen.

    Add a LogDownloadErrorHandler to the downloadAsync function.

  • VinayVinay

    @Eric said:
    What are the specs of your board? Post a screen shot from the MetaBase diagnostic screen.

    Add a LogDownloadErrorHandler to the downloadAsync function.

    I changed the LogDownloadUpdateHandler() to LogDownloadErrorHandler() and Logged errorType.name(). I didnt get a Log in Logcat so I assume the Download Error never occurred.

  • EricEric

    In the log tests that you posted, did you ever disconnect from the board in between the tests or did you go straight into another round of testing after the log download completed?

  • VinayVinay

    @Eric said:
    In the log tests that you posted, did you ever disconnect from the board in between the tests or did you go straight into another round of testing after the log download completed?

    I went straight into another round of testing.

    However, I am unable to log and download more data even if I disconnect, connect again and start logging.
    I even reset the board by introducing ``debug.resetAfterGc()''and it didn't work. I have to restart my app to get the device to log data.

  • EricEric

    For MetaWear C, the firmware cannot erase the time flash memory while connected so you need to disconnect after the log download completes.

    The main problem in your code is that you are only adding the data route once. Routes are no longer valid if the board resets or you call tearDown.

  • VinayVinay
    edited January 2019

    @Eric said:
    For MetaWear C, the firmware cannot erase the time flash memory while connected so you need to disconnect after the log download completes.

    Ok. I didn't know that. Do either of MetaMotion C or MetaMotion R support the functionality of erasing flash memory when connected?

    The main problem in your code is that you are only adding the data route once. Routes are no longer valid if the board resets or you call tearDown.

    Yes. This was my mistake. I didnt reset accelerometer to null when the disconnect was successful. Including that in the successful disconnect solved the problem. I can now log the data after I disconnect when the flash is full.

    One last thing I wanted to confirm was that logging.start(true) will never work in case of a MetaWear C since the flash memory cannot be overwritten when connected?

  • EricEric

    @Vinay said:

    @Eric said:
    For MetaWear C, the firmware cannot erase the time flash memory while connected so you need to disconnect after the log download completes.

    Ok. I didn't know that. Do either of MetaMotion C or MetaMotion R support the functionality of erasing flash memory when connected?

    MetaMotion boards should be able to erase while connected though logging while connected is not a normal use case.

    Typically, if you can maintain a stable connection, you would stream the data. If instead, you need to log, you would periodically connect only to sync the data.

    One last thing I wanted to confirm was that logging.start(true) will never work in case of a MetaWear C since the flash memory cannot be overwritten when connected?

    That is correct. Though this raises the question of why you are logging data if you have a stable connection with your Android device.

  • VinayVinay

    That is correct. Though this raises the question of why you are logging data if you have a stable connection with your Android device.

    I am working on a time intensive use case of the accelerometer data. Hence, I need the timestamps on the data to be as accurate as possible. I ran a test initially with Streaming and Logging and found that while streaming, I get data at odd intervals though I have set the frequency at 12.5 Hz. I have the following example.

    V/Data :: x : 0.09832764 y : -0.11755371 z : 1.0435791 t : 1548059932226 diff : 1548059932226 (ignore)
V/Data :: x : 0.09802246 y : -0.118652344 z : 1.0527954 t : 1548059932265 diff : 39
V/Data :: x : 0.09814453 y : -0.1184082 z : 1.0499878 t : 1548059932353 diff : 88
V/Data :: x : 0.0982666 y : -0.11779785 z : 1.0493164 t : 1548059932443 diff : 90
V/Data :: x : 0.09820557 y : -0.11773682 z : 1.050354 t : 1548059932489 diff : 46
V/Data :: x : 0.09851074 y : -0.11730957 z : 1.0508423 t : 1548059932576 diff : 87
V/Data :: x : 0.09869385 y : -0.11798096 z : 1.0515137 t : 1548059932668 diff : 92
V/Data :: x : 0.0982666 y : -0.11853027 z : 1.050293 t : 1548059932804 diff : 136
V/Data :: x : 0.09863281 y : -0.11828613 z : 1.0507202 t : 1548059932849 diff : 45
V/Data :: x : 0.09765625 y : -0.11798096 z : 1.0504761 t : 1548059932894 diff : 45
V/Data :: x : 0.09838867 y : -0.11779785 z : 1.0508423 t : 1548059932984 diff : 90
V/Data :: x : 0.099243164 y : -0.11853027 z : 1.0505371 t : 1548059933073 diff : 89
V/Data :: x : 0.09838867 y : -0.11779785 z : 1.0504761 t : 1548059933207 diff : 134
V/Data :: x : 0.097717285 y : -0.11798096 z : 1.0501709 t : 1548059933252 diff : 45
V/Data :: x : 0.09881592 y : -0.11785889 z : 1.0510864 t : 1548059933298 diff : 46
V/Data :: x : 0.097595215 y : -0.11804199 z : 1.0508423 t : 1548059933389 diff : 91
V/Data :: x : 0.09814453 y : -0.11767578 z : 1.0501099 t : 1548059933478 diff : 89
V/Data :: x : 0.09851074 y : -0.1182251 z : 1.0504761 t : 1548059933570 diff : 92
V/Data :: x : 0.09887695 y : -0.11810303 z : 1.0501709 t : 1548059933658 diff : 88
V/Data :: x : 0.09851074 y : -0.11773682 z : 1.0508423 t : 1548059933703 diff : 45
V/Data :: x : 0.097839355 y : -0.1182251 z : 1.0510864 t : 1548059933794 diff : 91
V/Data :: x : 0.09790039 y : -0.11853027 z : 1.0502319 t : 1548059933882 diff : 88
V/Data :: x : 0.097839355 y : -0.11828613 z : 1.0506592 t : 1548059933973 diff : 91

    I have used data.timestamp().getTimeInMillis() as the function to get the timestamps. Ideally, the timestamps for consecutive datapoints should be 80 ms. However as we see, the difference between the timestamps of two consequent datapoints are very erratic.

    While with logging, I got more or less the same time difference between two datapoints. Hence, though I have a connection established at all times, I decided to use logging instead of streaming.

    By any chance is the timestamp difference expected to be so erratic in case of Streaming Data?

  • EricEric

    https://mbientlab.com/androiddocs/3/data_route.html#account

  • VinayVinay

    @Eric said:
    https://mbientlab.com/androiddocs/3/data_route.html#account

    That worked perfectly for streaming. Thankyou very much for your help @Eric.

Sign In or Register to comment.