title: Debugging slow ContentResolver query calls spending lots of time in "context switch"
body: <p>Occasionally Android system calls, such as <a href="http://developer.android.com/reference/android/content/ContentResolver.html#query(android.net.Uri%2C%20java.lang.String%5B%5D%2C%20java.lang.String%2C%20java.lang.String%5B%5D%2C%20java.lang.String)" rel="nofollow noreferrer">ContentResolver.query(...)</a>, can take 1000x times longer than normal, for example ~10 seconds for a single call that might normally complete in ~10 milliseconds. My question is how to identify cases like this, understand why it's happening and resolve the problem.</p>
  
  <p>The example below is retrieving the "user profile" on an Android system. On my Nexus 6 it normally takes ~10 milliseconds to do this. Older devices were similarly quick. Occasionally though it can 20+ seconds. Using traceview, it shows that virtually all the time is spent in "context switch":</p>
  
  <p><img src="https://i.stack.imgur.com/ClDsb.png" alt="enter image description here"></p>
  
  <p>My device unusually has ~7,000 contacts. For the "user profile" that I'm requesting, the result is only a single row. It's requested using <code>Uri.withAppendedPath(Profile.CONTENT_URI, Data.CONTENT_DIRECTORY)</code> - which I presume would be a common, optimized case. At the moment, the queries are done on the main thread, which may be complicating things... the Android documentation mentions that "you should do queries asynchronously on a separate thread". I will migrate to that in the future but I'm skeptical of that being the cause as it was working fine previously.</p>
  
  <p>Another surprising factor is the strange consistency. I have multiple queries in the app. For a sequence of runs, the "user profile" will be consistently slow then start being fast again and I can't reproduce the issue. Likewise other contact queries that aren't the user profile, will be fast and then become slow. For the past six months, all the queries have been fast through the Nexus 5 and Nexus 6 devices - this only appeared in the last week.</p>
  
  <p>The query:</p>
  
  <pre><code>Uri uri = Uri.withAppendedPath(Profile.CONTENT_URI, Data.CONTENT_DIRECTORY),
  Log.d(TAG, "getOwner: " + uri.toString());
  Cursor cur = mResolver.query(
      uri,
      PROJECTION,  // 6 columns
      null,
      null,
      Data.IS_PRIMARY + " DESC");
  Log.d(TAG, "getOwner: query count -  " + cur.getCount());
  </code></pre>
  
  <p>Log Output:</p>
  
  <pre><code>// NOTE 18 second gap between log entries
  19:20:33.134 D/ConnectActivity﹕ getOwner: URI: content://com.android.contacts/profile/data
  19:20:51.779 D/ConnectActivity﹕ getOwner: query count -  1
  </code></pre>
  
  <p>I still find this behaviour surprising and don't understand why it occurs.</p>