1 /* 2 * Copyright (C) 2010 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 18 // TODO: find AIDL for ContentResolver. add queryExtensible() returning struct{Cursor?,String? singleRow} 19 // -- would have to lazily do real requery(), registerContentObserver(), etc 20 21 package com.android.rpc_performance; 22 23 import android.app.Activity; 24 import android.content.ComponentName; 25 import android.content.ContentQueryMap; 26 import android.content.ContentResolver; 27 import android.content.ContentValues; 28 import android.content.IContentProvider; 29 import android.content.Context; 30 import android.content.Intent; 31 import android.content.ServiceConnection; 32 import android.content.pm.PackageManager; 33 import android.content.pm.ResolveInfo; 34 import android.content.res.Configuration; 35 import android.content.res.Resources; 36 import android.database.Cursor; 37 import android.database.SQLException; 38 import android.net.LocalSocket; 39 import android.net.LocalSocketAddress; 40 import android.net.Uri; 41 import android.os.Binder; 42 import android.os.Bundle; 43 import android.os.Debug; 44 import android.os.Handler; 45 import android.os.IBinder; 46 import android.os.Parcel; 47 import android.os.RemoteException; 48 import android.os.ServiceManager; 49 import android.os.SystemClock; 50 import android.os.StrictMode; 51 import android.telephony.TelephonyManager; 52 import android.text.TextUtils; 53 import android.util.AndroidException; 54 import android.util.Config; 55 import android.util.Log; 56 import android.view.View; 57 import android.widget.Button; 58 import android.widget.TextView; 59 60 import java.io.File; 61 import java.io.FileInputStream; 62 import java.io.IOException; 63 import java.io.InputStream; 64 import java.io.OutputStream; 65 import java.io.RandomAccessFile; 66 67 public class ProviderPerfActivity extends Activity { 68 69 private static final String TAG = "ProviderPerfActivity"; 70 private static final Uri SYSTEM_SETTINGS_URI = Uri.parse("content://settings/system"); 71 72 // No-op provider URLs: 73 private static final Uri CROSS_PROC_PROVIDER_URI = Uri.parse("content://com.android.rpc_performance/"); 74 private static final Uri IN_PROC_PROVIDER_URI = Uri.parse("content://com.android.rpc_performance.local/"); 75 76 private final Handler mHandler = new Handler(); 77 private final static int LOOP_TIME_MILLIS = 2000; 78 private final static long LOOP_TIME_NANOS = (long) LOOP_TIME_MILLIS * 1000000L; 79 80 private IService mServiceStub = null; 81 private ServiceConnection serviceConnection = new ServiceConnection() { 82 public void onServiceConnected(ComponentName name, IBinder service) { 83 mServiceStub = IService.Stub.asInterface(service); 84 Log.v(TAG, "Service bound"); 85 } 86 87 public void onServiceDisconnected(ComponentName name) { 88 mServiceStub = null; 89 Log.v(TAG, "Service unbound"); 90 }; 91 }; 92 93 94 private ContentResolver cr; 95 private int mIterations = 100; 96 private String mTraceName = null; 97 98 /** Called when the activity is first created. */ 99 @Override 100 public void onCreate(Bundle savedInstanceState) { 101 super.onCreate(savedInstanceState); 102 setContentView(R.layout.main); 103 104 cr = getContentResolver(); 105 106 setButtonAction(R.id.file_read_button, new Runnable() { 107 public void run() { 108 final float avgTime = fileReadLoop(); 109 endAsyncOp(R.id.file_read_button, R.id.file_read_text, avgTime); 110 }}); 111 112 setButtonAction(R.id.file_write_button, new Runnable() { 113 public void run() { 114 final float avgTime = fileWriteLoop(); 115 endAsyncOp(R.id.file_write_button, R.id.file_write_text, avgTime); 116 }}); 117 118 setButtonAction(R.id.settings_read_button, new Runnable() { 119 public void run() { 120 final float avgTime = settingsProviderLoop(MODE_READ, 0); 121 endAsyncOp(R.id.settings_read_button, R.id.settings_read_text, avgTime); 122 }}); 123 124 setButtonAction(R.id.settings_sleep_button, new Runnable() { 125 public void run() { 126 final float avgTime = settingsProviderLoop(MODE_READ, 100); 127 endAsyncOp(R.id.settings_sleep_button, R.id.settings_sleep_text, avgTime); 128 }}); 129 130 setButtonAction(R.id.settings_write_button, new Runnable() { 131 public void run() { 132 final float avgTime = settingsProviderLoop(MODE_WRITE, 0); 133 endAsyncOp(R.id.settings_write_button, R.id.settings_write_text, avgTime); 134 }}); 135 136 setButtonAction(R.id.settings_writedup_button, new Runnable() { 137 public void run() { 138 final float avgTime = settingsProviderLoop(MODE_WRITE_DUP, 0); 139 endAsyncOp(R.id.settings_writedup_button, R.id.settings_writedup_text, avgTime); 140 }}); 141 142 setButtonAction(R.id.dummy_lookup_button, new Runnable() { 143 public void run() { 144 final float avgTime = noOpProviderLoop(CROSS_PROC_PROVIDER_URI); 145 endAsyncOp(R.id.dummy_lookup_button, R.id.dummy_lookup_text, avgTime); 146 }}); 147 148 setButtonAction(R.id.dummy_local_lookup_button, new Runnable() { 149 public void run() { 150 final float avgTime = noOpProviderLoop(IN_PROC_PROVIDER_URI); 151 endAsyncOp(R.id.dummy_local_lookup_button, 152 R.id.dummy_local_lookup_text, avgTime); 153 }}); 154 155 setButtonAction(R.id.localsocket_button, new Runnable() { 156 public void run() { 157 final float avgTime = localSocketLoop(); 158 endAsyncOp(R.id.localsocket_button, R.id.localsocket_text, avgTime); 159 }}); 160 161 setButtonAction(R.id.service_button, new Runnable() { 162 public void run() { 163 final float avgTime = serviceLoop(null); 164 endAsyncOp(R.id.service_button, R.id.service_text, avgTime); 165 }}); 166 167 setButtonAction(R.id.service2_button, new Runnable() { 168 public void run() { 169 final float avgTime = serviceLoop("xyzzy"); 170 endAsyncOp(R.id.service2_button, R.id.service2_text, avgTime); 171 }}); 172 173 setButtonAction(R.id.ping_media_button, new Runnable() { 174 public void run() { 175 final float avgTime = pingServiceLoop("media.player"); 176 endAsyncOp(R.id.ping_media_button, R.id.ping_media_text, avgTime); 177 }}); 178 179 setButtonAction(R.id.ping_activity_button, new Runnable() { 180 public void run() { 181 final float avgTime = pingServiceLoop("activity"); 182 endAsyncOp(R.id.ping_activity_button, R.id.ping_activity_text, avgTime); 183 }}); 184 185 setButtonAction(R.id.proc_button, new Runnable() { 186 public void run() { 187 final float avgTime = procLoop(); 188 endAsyncOp(R.id.proc_button, R.id.proc_text, avgTime); 189 }}); 190 191 setButtonAction(R.id.call_button, new Runnable() { 192 public void run() { 193 final float avgTime = callLoop("ringtone"); 194 endAsyncOp(R.id.call_button, R.id.call_text, avgTime); 195 }}); 196 197 setButtonAction(R.id.call2_button, new Runnable() { 198 public void run() { 199 final float avgTime = callLoop("XXXXXXXX"); // non-existent 200 endAsyncOp(R.id.call2_button, R.id.call2_text, avgTime); 201 }}); 202 203 setButtonAction(R.id.obtain_button, new Runnable() { 204 public void run() { 205 final float avgTime = parcelLoop(true); 206 endAsyncOp(R.id.obtain_button, R.id.obtain_text, avgTime); 207 }}); 208 209 setButtonAction(R.id.recycle_button, new Runnable() { 210 public void run() { 211 final float avgTime = parcelLoop(false); 212 endAsyncOp(R.id.recycle_button, R.id.recycle_text, avgTime); 213 }}); 214 215 setButtonAction(R.id.strictmode_button, new Runnable() { 216 public void run() { 217 final float avgTime = strictModeLoop(true); 218 endAsyncOp(R.id.strictmode_button, R.id.strictmode_text, avgTime); 219 }}); 220 221 setButtonAction(R.id.binderstrict_button, new Runnable() { 222 public void run() { 223 final float avgTime = strictModeLoop(false); 224 endAsyncOp(R.id.binderstrict_button, R.id.binderstrict_text, avgTime); 225 }}); 226 } 227 228 @Override public void onResume() { 229 super.onResume(); 230 231 bindService(new Intent(this, MiscService.class), 232 serviceConnection, Context.BIND_AUTO_CREATE); 233 } 234 235 @Override public void onPause() { 236 super.onPause(); 237 if (serviceConnection != null) { 238 unbindService(serviceConnection); 239 } 240 } 241 242 private void setButtonAction(int button_id, final Runnable r) { 243 final Button button = (Button) findViewById(button_id); 244 button.setOnClickListener(new View.OnClickListener() { 245 public void onClick(View v) { 246 button.requestFocus(); 247 button.setEnabled(false); 248 249 TextView tvIter = (TextView) findViewById(R.id.iterations_edit); 250 try { 251 mIterations = Integer.parseInt(tvIter.getText().toString()); 252 } catch (NumberFormatException e) { 253 Log.w(TAG, "Invalid iteration count", e); 254 if (tvIter != null) tvIter.setText(Integer.toString(mIterations)); 255 } 256 257 TextView tvTrace = (TextView) findViewById(R.id.trace_edit); 258 String name = tvTrace.getText().toString(); 259 if (name != null && name.length() > 0) { 260 mTraceName = name; 261 Debug.startMethodTracing(name); 262 } 263 264 new Thread(r).start(); 265 } 266 }); 267 } 268 269 private void endAsyncOp(final int button_id, final int text_id, final float avgTime) { 270 mHandler.post(new Runnable() { 271 public void run() { 272 Debug.stopMethodTracing(); 273 findViewById(button_id).setEnabled(true); 274 setTextTime(text_id, avgTime); 275 } 276 }); 277 } 278 279 private void setTextTime(int id, float avgTime) { 280 TextView tv = (TextView) findViewById(id); 281 if (tv == null) return; 282 String text = tv.getText().toString(); 283 text = text.substring(0, text.indexOf(':') + 1) + "\n" + avgTime + " ms avg"; 284 tv.setText(text); 285 } 286 287 private float fileReadLoop() { 288 RandomAccessFile raf = null; 289 File filename = getFileStreamPath("test.dat"); 290 try { 291 long sumNanos = 0; 292 byte[] buf = new byte[512]; 293 294 raf = new RandomAccessFile(filename, "rw"); 295 raf.write(buf); 296 raf.close(); 297 raf = null; 298 299 // The data's almost certainly cached -- it's not clear what we're testing here 300 raf = new RandomAccessFile(filename, "r"); 301 for (int i = 0; i < mIterations; i++) { 302 long lastTime = System.nanoTime(); 303 raf.seek(0); 304 raf.read(buf); 305 sumNanos += System.nanoTime() - lastTime; 306 } 307 308 return (float) sumNanos / Math.max(1.0f, (float) mIterations) / 1000000.0f; 309 } catch (IOException e) { 310 Log.e(TAG, "File read failed", e); 311 return 0; 312 } finally { 313 try { if (raf != null) raf.close(); } catch (IOException e) {} 314 } 315 } 316 317 private float fileWriteLoop() { 318 RandomAccessFile raf = null; 319 File filename = getFileStreamPath("test.dat"); 320 try { 321 long sumNanos = 0; 322 byte[] buf = new byte[512]; 323 for (int i = 0; i < mIterations; i++) { 324 for (int j = 0; j < buf.length; j++) buf[j] = (byte) (i + j); 325 long lastTime = System.nanoTime(); 326 raf = new RandomAccessFile(filename, "rw"); 327 raf.write(buf); 328 raf.close(); 329 raf = null; 330 sumNanos += System.nanoTime() - lastTime; 331 } 332 333 return (float) sumNanos / Math.max(1.0f, (float) mIterations) / 1000000.0f; 334 } catch (IOException e) { 335 Log.e(TAG, "File read failed", e); 336 return 0; 337 } finally { 338 try { if (raf != null) raf.close(); } catch (IOException e) {} 339 } 340 } 341 342 // Returns average cross-process dummy query time in milliseconds. 343 private float noOpProviderLoop(Uri uri) { 344 long sumNanos = 0; 345 int failures = 0; 346 int total = 0; 347 for (int i = 0; i < mIterations; i++) { 348 long duration = doNoOpLookup(uri); 349 if (duration < 0) { 350 failures++; 351 } else { 352 total++; 353 sumNanos += duration; 354 } 355 } 356 float averageMillis = (float) sumNanos / 357 (float) (total != 0 ? total : 1) / 358 1000000.0f; 359 Log.v(TAG, "dummy loop: fails=" + failures + "; total=" + total + "; goodavg ms=" + averageMillis); 360 return averageMillis; 361 } 362 363 // Returns average cross-process dummy query time in milliseconds. 364 private float callLoop(String key) { 365 IContentProvider cp = cr.acquireProvider(SYSTEM_SETTINGS_URI.getAuthority()); 366 367 long sumNanos = 0; 368 int total = 0; 369 370 try { 371 for (int i = 0; i < mIterations; i++) { 372 long lastTime = System.nanoTime(); 373 Bundle b = cp.call("GET_system", key, null); 374 long nowTime = System.nanoTime(); 375 total++; 376 sumNanos += (nowTime - lastTime); 377 } 378 } catch (RemoteException e) { 379 return -999.0f; 380 } 381 float averageMillis = (float) sumNanos / 382 (float) (total != 0 ? total : 1) / 383 1000000.0f; 384 Log.v(TAG, "call loop: avg_ms=" + averageMillis + "; calls=" + total); 385 return averageMillis; 386 } 387 388 // Returns average time to read a /proc file in milliseconds. 389 private float procLoop() { 390 long sumNanos = 0; 391 int total = 0; 392 File f = new File("/proc/self/cmdline"); 393 byte[] buf = new byte[100]; 394 String value = null; 395 try { 396 for (int i = 0; i < mIterations; i++) { 397 long lastTime = System.nanoTime(); 398 FileInputStream is = new FileInputStream(f); 399 int readBytes = is.read(buf, 0, 100); 400 is.close(); 401 //value = new String(buf, 0, readBytes); 402 long nowTime = System.nanoTime(); 403 total++; 404 sumNanos += (nowTime - lastTime); 405 lastTime = nowTime; 406 } 407 } catch (IOException e) { 408 return -999.0f; 409 } 410 float averageMillis = (float) sumNanos / 411 (float) (total != 0 ? total : 1) / 412 1000000.0f; 413 Log.v(TAG, "proc loop: total: " + total + "; avg_ms=" + averageMillis + "; value=" + value); 414 return averageMillis; 415 } 416 417 private static final String[] IGNORED_COLUMN = {"ignored"}; 418 419 // Returns nanoseconds. 420 private long doNoOpLookup(Uri uri) { 421 Cursor c = null; 422 try { 423 long startTime = System.nanoTime(); 424 c = cr.query(uri, 425 IGNORED_COLUMN, //new String[]{"ignored"}, // but allocate it for apples-to-apples 426 "name=?", 427 IGNORED_COLUMN, // new String[]{"also_ignored"}, // also for equality in benchmarking 428 null /* sort order */); 429 if (c == null) { 430 Log.w(TAG, "cursor null"); 431 return -1; 432 } 433 String value = c.moveToNext() ? c.getString(0) : null; 434 long duration = System.nanoTime() - startTime; 435 //Log.v(TAG, "got value: " + value + " in " + duration); 436 return duration; 437 } catch (SQLException e) { 438 Log.w(TAG, "sqlite exception: " + e); 439 return -1; 440 } finally { 441 if (c != null) c.close(); 442 } 443 } 444 445 // Returns average cross-process dummy query time in milliseconds. 446 private float serviceLoop(String value) { 447 if (mServiceStub == null) { 448 Log.v(TAG, "No service stub."); 449 return -999; 450 } 451 452 String dummy = null; 453 try { 454 if (mTraceName != null) mServiceStub.startTracing(mTraceName + ".service"); 455 456 long sumNanos = 0; 457 for (int i = 0; i < mIterations; i++) { 458 long lastTime = System.nanoTime(); 459 if (value == null) { 460 mServiceStub.pingVoid(); 461 } else { 462 value = mServiceStub.pingString(value); 463 } 464 sumNanos += System.nanoTime() - lastTime; 465 } 466 467 if (mTraceName != null) mServiceStub.stopTracing(); 468 469 return (float) sumNanos / Math.max(1.0f, (float) mIterations) / 1000000.0f; 470 } catch (RemoteException e) { 471 Log.e(TAG, "Binder call failed", e); 472 return -999; 473 } 474 } 475 476 // Returns average cross-process binder ping time in milliseconds. 477 private float pingServiceLoop(String service) { 478 IBinder binder = ServiceManager.getService(service); 479 if (binder == null) { 480 Log.e(TAG, "Service missing: " + service); 481 return -1.0f; 482 } 483 484 long sumNanos = 0; 485 for (int i = 0; i < mIterations; i++) { 486 long lastTime = System.nanoTime(); 487 if (!binder.pingBinder()) { 488 Log.e(TAG, "Error pinging service: " + service); 489 return -1.0f; 490 } 491 sumNanos += System.nanoTime() - lastTime; 492 } 493 494 return (float) sumNanos / Math.max(1.0f, (float) mIterations) / 1000000.0f; 495 } 496 497 // Returns average milliseconds. 498 private float localSocketLoop() { 499 LocalSocket socket = null; 500 try { 501 socket = new LocalSocket(); 502 Log.v(TAG, "Connecting to socket..."); 503 socket.connect(new LocalSocketAddress(MiscService.SOCKET_NAME)); 504 Log.v(TAG, "Connected to socket."); 505 InputStream is = socket.getInputStream(); 506 OutputStream os = socket.getOutputStream(); 507 508 int count = 0; 509 long sumNanos = 0; 510 for (int i = 0; i < mIterations; i++) { 511 long beforeTime = System.nanoTime(); 512 int expectByte = count & 0xff; 513 os.write(expectByte); 514 int gotBackByte = is.read(); 515 516 long afterTime = System.nanoTime(); 517 sumNanos += (afterTime - beforeTime); 518 519 if (gotBackByte != expectByte) { 520 Log.w(TAG, "Got wrong byte back. Got: " + gotBackByte 521 + "; wanted=" + expectByte); 522 return -999.00f; 523 } 524 count++; 525 } 526 return count == 0 ? 0.0f : ((float) sumNanos / (float) count / 1000000.0f); 527 } catch (IOException e) { 528 Log.v(TAG, "error in localSocketLoop: " + e); 529 return -1.0f; 530 } finally { 531 if (socket != null) { 532 try { socket.close(); } catch (IOException e) {} 533 } 534 } 535 } 536 537 // Returns average operation time in milliseconds. 538 // obtain: true = measure obtain(), false = measure recycle() 539 private float parcelLoop(boolean obtain) { 540 long sumNanos = 0; 541 for (int i = 0; i < mIterations; i++) { 542 if (obtain) { 543 long lastTime = System.nanoTime(); 544 Parcel p = Parcel.obtain(); 545 sumNanos += System.nanoTime() - lastTime; 546 p.recycle(); 547 } else { 548 Parcel p = Parcel.obtain(); 549 long lastTime = System.nanoTime(); 550 p.recycle(); 551 sumNanos += System.nanoTime() - lastTime; 552 } 553 } 554 555 return (float) sumNanos / Math.max(1.0f, (float) mIterations) / 1000000.0f; 556 } 557 558 private float strictModeLoop(boolean full) { 559 StrictMode.ThreadPolicy oldPolicy = StrictMode.getThreadPolicy(); 560 int oldPolicyMask = StrictMode.getThreadPolicyMask(); // hidden API 561 long sumNanos = 0; 562 StrictMode.ThreadPolicy policyA = 563 new StrictMode.ThreadPolicy.Builder().detectDiskReads().build(); 564 StrictMode.ThreadPolicy policyB = 565 new StrictMode.ThreadPolicy.Builder().detectDiskWrites().build(); 566 for (int i = 0; i < mIterations; i++) { 567 StrictMode.ThreadPolicy policy = ((i & 1) == 1) ? policyA : policyB; 568 int policyMask = ((i & 1) == 1) ? 1 : 2; 569 if (full) { 570 long lastTime = System.nanoTime(); 571 StrictMode.setThreadPolicy(policy); 572 sumNanos += System.nanoTime() - lastTime; 573 } else { 574 long lastTime = System.nanoTime(); 575 Binder.setThreadStrictModePolicy(policyMask); 576 sumNanos += System.nanoTime() - lastTime; 577 } 578 } 579 if (full) { 580 StrictMode.setThreadPolicy(oldPolicy); 581 } else { 582 Binder.setThreadStrictModePolicy(oldPolicyMask); 583 } 584 return (float) sumNanos / Math.max(1.0f, (float) mIterations) / 1000000.0f; 585 } 586 587 // Returns average milliseconds. 588 private static final int MODE_READ = 0; 589 private static final int MODE_WRITE = 1; 590 private static final int MODE_WRITE_DUP = 2; 591 592 private float settingsProviderLoop(int mode, long innerSleep) { 593 long sumMillis = 0; 594 int total = 0; 595 for (int i = 0; i < mIterations; i++) { 596 long duration = mode == MODE_READ ? settingsRead(innerSleep) : settingsWrite(mode); 597 if (duration < 0) { 598 return -999.0f; 599 } 600 total++; 601 sumMillis += duration; 602 } 603 float averageMillis = ((float) sumMillis / (float) (total != 0 ? total : 1)); 604 Log.v(TAG, "settings provider; mode=" + mode + "; total=" + total + 605 "; goodavg_ms=" + averageMillis); 606 return averageMillis; 607 } 608 609 // Returns milliseconds taken, or -1 on failure. 610 private long settingsRead(long innerSleep) { 611 Cursor c = null; 612 try { 613 long startTime = SystemClock.uptimeMillis(); 614 c = cr.query(SYSTEM_SETTINGS_URI, 615 new String[]{"value"}, 616 "name=?", 617 new String[]{"airplane_mode_on"}, 618 null /* sort order */); 619 if (c == null) { 620 Log.w(TAG, "cursor null"); 621 return -1; 622 } 623 String value = c.moveToNext() ? c.getString(0) : null; 624 long duration = SystemClock.uptimeMillis() - startTime; 625 if (innerSleep > 0) { 626 try { 627 Thread.sleep(innerSleep); 628 } catch (InterruptedException e) {} 629 } 630 return duration; 631 } catch (SQLException e) { 632 Log.w(TAG, "sqlite exception: " + e); 633 return -1; 634 } finally { 635 if (c != null) c.close(); 636 } 637 } 638 639 // Returns milliseconds taken, or -1 on failure. 640 private long settingsWrite(int mode) { 641 Cursor c = null; 642 long startTime = SystemClock.uptimeMillis(); 643 // The database will take care of replacing duplicates. 644 try { 645 ContentValues values = new ContentValues(); 646 values.put("name", "dummy_for_testing"); 647 values.put("value", (mode == MODE_WRITE ? (""+startTime) : "foo")); 648 Uri uri = cr.insert(SYSTEM_SETTINGS_URI, values); 649 Log.v(TAG, "inserted uri: " + uri); 650 } catch (SQLException e) { 651 Log.w(TAG, "sqliteexception during write: " + e); 652 return -1; 653 } 654 long duration = SystemClock.uptimeMillis() - startTime; 655 return duration; 656 } 657 } 658