Time required by some statements to execute not constant

Question

Inside my SQLite Adapter class, for an Android application, I have the following method. The key KEY_WAS can be either 0 or 1. The method searches for a given name and a given date in the database (for a given date there can only be one unique entry for a particular name in the DB). So, if such an entry is present, we go inside if, otherwise was remains zero. Finally, was is returned.

public int wasHere(String name, String date) throws SQLException {
    Log.d("wasHere", "begins, date = " + date);
    Cursor c = ourDatabase.query(DATABASE_TABLE, ALL_KEYS, KEY_NAME
            + "=" + "'" + name + "'" + " AND " + KEY_DATE + "=" + "'"
            + date + "'", null, null, null, null);
    Log.d("wasHere", "below Cursor");
    int was = 0;
    if(c.moveToFirst()) {
        Log.d("wasHere", "inside IF");
        was = c.getInt(c.getColumnIndex(KEY_WAS));
    }
    Lod.d("wasHere", "ends");
    return was;
}

From the log entries, I am pasting some particular ones (you can ignore the time between "begins" and "ends" as that depends on the loop which is calling wasHere):

07-18 07:08:03.398: D/dbwas(29568): begins, date = 08 Aug 2013
07-18 07:08:03.398: D/dbwas(29568): below cursor
07-18 07:08:03.398: D/dbwas(29568): ends

07-18 07:08:03.398: D/dbwas(29568): begins, date = 09 Aug 2013
07-18 07:08:03.406: D/dbwas(29568): below cursor
07-18 07:08:03.406: D/dbwas(29568): ends

07-18 07:08:03.359: D/dbwas(29568): begins, date = 02 Aug 2013
07-18 07:08:03.359: D/dbwas(29568): below cursor
07-18 07:08:03.367: D/dbwas(29568): inside IF
07-18 07:08:03.367: D/dbwas(29568): ends

07-18 07:08:03.367: D/dbwas(29568): begins, date = 03 Aug 2013
07-18 07:08:03.367: D/dbwas(29568): below cursor
07-18 07:08:03.375: D/dbwas(29568): inside IF
07-18 07:08:03.375: D/dbwas(29568): ends

07-18 07:08:03.430: D/dbwas(29568): begins, date = 14 Aug 2013
07-18 07:08:03.430: D/dbwas(29568): below cursor
07-18 07:08:03.430: D/dbwas(29568): inside IF
07-18 07:08:03.430: D/dbwas(29568): ends

My question is regarding the log times for "begins" and "ends". As you can see above, among the five log entries, two (8 Aug and 14 Aug) take 0 time from "begins, date = ..." to "ends".

9 Aug takes 8 ms (.008 seconds) in executing the Cursor statement.

2 Aug and 3 Aug take 8 ms (.008 seconds) in executing the if statement.

14 Aug takes no time is executing either of the two above mentioned statements.

Similarly, there are many such discrepancies in the "log". For different dates, the Cursor and if statements randomly take 8 ms (and yes, the time is always 8 ms).

Now, I am executing "wasHere" method hundreds of times, so hundreds of 8 milliseconds cost me too much time. Why are the above discrepancies happening randomly. And is there any way to remove it (or maybe another way of doing what I am doing). [8 Aug and 14 Aug statement take zero time as they should.]

Answer 1

On your system, the timer interrupt apparently runs at 125 Hz and thus happens every 8 ms. If your function gets executed completely between two timer interrupts, you will see no change in the timestamps, but if a timer interrupt happens while your function is executing, you will see a jump of 8 ms.

There is no discrepancy in the actual execution times; the timestamps in your log are just not precise enough.