android/okhttp
1
0
Fork 0
mirror of https://github.com/square/okhttp.git synced 2025-08-07 12:42:57 +03:00
Code Releases Activity

Document debug logging.

Browse Source 
Also refine the formatting of TaskRunner logging.

Before:

    [2019-12-30 16:43:19] Q1 starting: OkHttp ConnectionPool
    [2019-12-30 16:43:19] Q1 scheduled after 300 s: OkHttp ConnectionPool
    [2019-12-30 16:43:19] Q1 finished in 94 µs: OkHttp ConnectionPool
    [2019-12-30 16:43:19] Q359 scheduled after 0 µs: OkHttp www.youtube.com applyAndAckSettings
    [2019-12-30 16:43:19] Q359 starting: OkHttp www.youtube.com applyAndAckSettings
    [2019-12-30 16:43:19] Q361 schedule canceled (queue is shutdown): OkHttp www.youtube.com onSettings
    [2019-12-30 16:43:19] Q359 finished in 382 µs: OkHttp www.youtube.com applyAndAckSettings
    [2019-12-30 16:43:20] Q1 scheduled after 0 µs: OkHttp ConnectionPool
    [2019-12-30 16:43:20] Q365 scheduled after 0 µs: OkHttp android-developers.googleblog.com applyAndAckSettings
    [2019-12-30 16:43:20] Q1 starting: OkHttp ConnectionPool
    [2019-12-30 16:43:20] Q365 starting: OkHttp android-developers.googleblog.com applyAndAckSettings
    [2019-12-30 16:43:20] Q1 scheduled after 300 s: OkHttp ConnectionPool
    [2019-12-30 16:43:20] Q1 finished in 151 µs: OkHttp ConnectionPool

After:

    [2019-12-30 16:43:19] Q10001 starting              : OkHttp ConnectionPool
    [2019-12-30 16:43:19] Q10001 run again after 300 s : OkHttp ConnectionPool
    [2019-12-30 16:43:19] Q10001 finished run in  94 µs: OkHttp ConnectionPool
    [2019-12-30 16:43:19] Q10359 scheduled after   0 µs: OkHttp www.youtube.com applyAndAckSettings
    [2019-12-30 16:43:19] Q10359 starting              : OkHttp www.youtube.com applyAndAckSettings
    [2019-12-30 16:43:19] Q10361 schedule canceled (queue is shutdown): OkHttp www.youtube.com onSettings
    [2019-12-30 16:43:19] Q10359 finished run in 382 µs: OkHttp www.youtube.com applyAndAckSettings
    [2019-12-30 16:43:20] Q10001 scheduled after   0 µs: OkHttp ConnectionPool
    [2019-12-30 16:43:20] Q10365 scheduled after   0 µs: OkHttp android-developers.googleblog.com applyAndAckSettings
    [2019-12-30 16:43:20] Q10001 starting              : OkHttp ConnectionPool
    [2019-12-30 16:43:20] Q10365 starting              : OkHttp android-developers.googleblog.com applyAndAckSettings
    [2019-12-30 16:43:20] Q10001 run again after 300 s : OkHttp ConnectionPool
    [2019-12-30 16:43:20] Q10001 finished run in 151 µs: OkHttp ConnectionPool
This commit is contained in:
Jesse Wilson
2019-12-30 17:43:54 -05:00
parent b9e042284b
commit a815093721
9 changed files with 307 additions and 139 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
CONTRIBUTING.md
View File

@@ -36,10 +36,12 @@ Committer's Guides
------------------ ------------------
* [Concurrency][concurrency] * [Concurrency][concurrency]
* [Debug Logging][debug_logging]
* [Releasing][releasing] * [Releasing][releasing]
[cla]: https://spreadsheets.google.com/spreadsheet/viewform?formkey=dDViT2xzUHAwRkI3X3k5Z0lQM091OGc6MQ&ndplr=1 [cla]: https://spreadsheets.google.com/spreadsheet/viewform?formkey=dDViT2xzUHAwRkI3X3k5Z0lQM091OGc6MQ&ndplr=1
[concurrency]: http://square.github.io/okhttp/concurrency/ [concurrency]: http://square.github.io/okhttp/concurrency/
[debug_logging]: http://square.github.io/okhttp/debug_logging/
[releasing]: http://square.github.io/okhttp/releasing/ [releasing]: http://square.github.io/okhttp/releasing/
[security]: http://square.github.io/okhttp/security/ [security]: http://square.github.io/okhttp/security/
[works_with_okhttp]: http://square.github.io/okhttp/works_with_okhttp/ [works_with_okhttp]: http://square.github.io/okhttp/works_with_okhttp/

53
android-test/src/androidTest/java/okhttp/android/test/OkHttpDebugLogcat.kt Normal file
View File

@@ -0,0 +1,53 @@
/*
* Copyright (C) 2019 Square, Inc.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package okhttp.android.test
import android.util.Log
import okhttp3.internal.concurrent.TaskRunner
import okhttp3.internal.http2.Http2
import java.util.concurrent.CopyOnWriteArraySet
import java.util.logging.Handler
import java.util.logging.Level
import java.util.logging.LogRecord
import java.util.logging.Logger
import kotlin.reflect.KClass
object OkHttpDebugLogcat {
// Keep references to loggers to prevent their configuration from being GC'd.
private val configuredLoggers = CopyOnWriteArraySet<Logger>()
fun enableHttp2() = enable(Http2::class)
fun enableTaskRunner() = enable(TaskRunner::class)
private fun enable(loggerClass: KClass<*>) {
val logger = Logger.getLogger(loggerClass.java.name)
if (configuredLoggers.add(logger)) {
logger.level = Level.FINE
logger.addHandler(object : Handler() {
override fun publish(record: LogRecord) {
Log.i(loggerClass.simpleName, record.message, record.thrown)
}
override fun flush() {
}
override fun close() {
}
})
}
}
}

57
docs/debug_logging.md Normal file
View File

@@ -0,0 +1,57 @@
Debug Logging
=============
OkHttp has internal APIs to enable debug logging. It uses the `java.util.logging` API which can be
tricky to configure. As a shortcut, you can paste [OkHttpDebugLogging.kt]. Then enable debug logging
for whichever features you need:
```
OkHttpDebugLogging.enableHttp2()
OkHttpDebugLogging.enableTaskRunner()
```
On Android, use [OkHttpDebugLogcat.kt] instead. It connects OkHttp logs to Logcat in Android Studio.
### HTTP/2 Frame Logging
This logs inbound (`<<`) and outbound (`>>`) frames for HTTP/2 connections.
```
[2020-01-01 00:00:00] >> CONNECTION 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a
[2020-01-01 00:00:00] >> 0x00000000 6 SETTINGS
[2020-01-01 00:00:00] >> 0x00000000 4 WINDOW_UPDATE
[2020-01-01 00:00:00] >> 0x00000003 47 HEADERS END_STREAM|END_HEADERS
[2020-01-01 00:00:00] << 0x00000000 6 SETTINGS
[2020-01-01 00:00:00] << 0x00000000 0 SETTINGS ACK
[2020-01-01 00:00:00] << 0x00000000 4 WINDOW_UPDATE
[2020-01-01 00:00:00] >> 0x00000000 0 SETTINGS ACK
[2020-01-01 00:00:00] << 0x00000003 322 HEADERS END_HEADERS
[2020-01-01 00:00:00] << 0x00000003 288 DATA
[2020-01-01 00:00:00] << 0x00000003 0 DATA END_STREAM
[2020-01-01 00:00:00] << 0x00000000 8 GOAWAY
[2020-01-01 00:00:05] << 0x00000000 8 GOAWAY
```
### Task Runner Logging
This logs task enqueues, starts, and finishes.
```
[2020-01-01 00:00:00] Q10000 scheduled after 0 µs: OkHttp ConnectionPool
[2020-01-01 00:00:00] Q10000 starting : OkHttp ConnectionPool
[2020-01-01 00:00:00] Q10000 run again after 300 s : OkHttp ConnectionPool
[2020-01-01 00:00:00] Q10000 finished run in 1 ms: OkHttp ConnectionPool
[2020-01-01 00:00:00] Q10001 scheduled after 0 µs: OkHttp squareup.com applyAndAckSettings
[2020-01-01 00:00:00] Q10001 starting : OkHttp squareup.com applyAndAckSettings
[2020-01-01 00:00:00] Q10003 scheduled after 0 µs: OkHttp squareup.com onSettings
[2020-01-01 00:00:00] Q10003 starting : OkHttp squareup.com onSettings
[2020-01-01 00:00:00] Q10001 finished run in 3 ms: OkHttp squareup.com applyAndAckSettings
[2020-01-01 00:00:00] Q10003 finished run in 528 µs: OkHttp squareup.com onSettings
[2020-01-01 00:00:00] Q10000 scheduled after 0 µs: OkHttp ConnectionPool
[2020-01-01 00:00:00] Q10000 starting : OkHttp ConnectionPool
[2020-01-01 00:00:00] Q10000 run again after 300 s : OkHttp ConnectionPool
[2020-01-01 00:00:00] Q10000 finished run in 739 µs: OkHttp ConnectionPool
```
[OkHttpDebugLogging.kt]: https://github.com/square/okhttp/blob/master/okhttp-testing-support/src/main/java/okhttp3/OkHttpDebugLogging.kt
[OkHttpDebugLogcat.kt]: https://github.com/square/okhttp/blob/master/android-test/src/androidTest/java/okhttp/android/test/OkHttpDebugLogcat.kt

49
okhttp-testing-support/src/main/java/okhttp3/OkHttpDebugLogging.kt Normal file
View File

@@ -0,0 +1,49 @@
/*
* Copyright (C) 2019 Square, Inc.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package okhttp3
import okhttp3.internal.concurrent.TaskRunner
import okhttp3.internal.http2.Http2
import java.util.concurrent.CopyOnWriteArraySet
import java.util.logging.ConsoleHandler
import java.util.logging.Level
import java.util.logging.LogRecord
import java.util.logging.Logger
import java.util.logging.SimpleFormatter
import kotlin.reflect.KClass
object OkHttpDebugLogging {
// Keep references to loggers to prevent their configuration from being GC'd.
private val configuredLoggers = CopyOnWriteArraySet<Logger>()
fun enableHttp2() = enable(Http2::class)
fun enableTaskRunner() = enable(TaskRunner::class)
private fun enable(loggerClass: KClass<*>) {
val logger = Logger.getLogger(loggerClass.java.name)
if (configuredLoggers.add(logger)) {
logger.addHandler(ConsoleHandler().apply {
level = Level.FINE
formatter = object : SimpleFormatter() {
override fun format(record: LogRecord) =
String.format("[%1\$tF %1\$tT] %2\$s %n", record.millis, record.message)
}
})
logger.level = Level.FINE
}
}
}

20
okhttp/src/main/java/okhttp3/internal/concurrent/TaskLogger.kt
View File

@@ -48,30 +48,34 @@ internal inline fun <T> logElapsed(
if (loggingEnabled) { if (loggingEnabled) {
val elapsedNs = queue.taskRunner.backend.nanoTime() - startNs val elapsedNs = queue.taskRunner.backend.nanoTime() - startNs
if (completedNormally) { if (completedNormally) {
log(task, queue, "finished in ${formatDuration(elapsedNs)}") log(task, queue, "finished run in ${formatDuration(elapsedNs)}")
} else { } else {
log(task, queue, "failed in ${formatDuration(elapsedNs)}") log(task, queue, "failed a run in ${formatDuration(elapsedNs)}")
} }
} }
} }
} }
private fun log(task: Task, queue: TaskQueue, message: String) { private fun log(task: Task, queue: TaskQueue, message: String) {
TaskRunner.logger.fine("${queue.name} $message: ${task.name}") TaskRunner.logger.fine("${queue.name} ${String.format("%-22s", message)}: ${task.name}")
} }
/** /**
* Returns a duration in the nearest whole-number units like "999 µs" or "1 ms". This rounds 0.5 * Returns a duration in the nearest whole-number units like "999 µs" or " 1 s ". This rounds 0.5
* units away from 0 and 0.499 towards 0. The smallest unit this returns is "µs"; the largest unit * units away from 0 and 0.499 towards 0. The smallest unit this returns is "µs"; the largest unit
* it returns is "s". For values in [-499..499] this returns "0 µs". * it returns is "s". For values in [-499..499] this returns " 0 µs".
*
* The returned string attempts to be column-aligned to 6 characters. For negative and large values
* the returned string may be longer.
*/ */
fun formatDuration(ns: Long): String { fun formatDuration(ns: Long): String {
return when { val s = when {
ns <= -999_500_000 -> "${(ns - 500_000_000) / 1_000_000_000} s" ns <= -999_500_000 -> "${(ns - 500_000_000) / 1_000_000_000} s "
ns <= -999_500 -> "${(ns - 500_000) / 1_000_000} ms" ns <= -999_500 -> "${(ns - 500_000) / 1_000_000} ms"
ns <= 0 -> "${(ns - 500) / 1_000} µs" ns <= 0 -> "${(ns - 500) / 1_000} µs"
ns < 999_500 -> "${(ns + 500) / 1_000} µs" ns < 999_500 -> "${(ns + 500) / 1_000} µs"
ns < 999_500_000 -> "${(ns + 500_000) / 1_000_000} ms" ns < 999_500_000 -> "${(ns + 500_000) / 1_000_000} ms"
else -> "${(ns + 500_000_000) / 1_000_000_000} s" else -> "${(ns + 500_000_000) / 1_000_000_000} s "
} }
return String.format("%6s", s)
} }

11
okhttp/src/main/java/okhttp3/internal/concurrent/TaskQueue.kt
View File

@@ -68,7 +68,7 @@ class TaskQueue internal constructor(
throw RejectedExecutionException() throw RejectedExecutionException()
} }
if (scheduleAndDecide(task, delayNanos)) { if (scheduleAndDecide(task, delayNanos, recurrence = false)) {
taskRunner.kickCoordinator(this) taskRunner.kickCoordinator(this)
} }
} }
@@ -122,7 +122,7 @@ class TaskQueue internal constructor(
// Don't delegate to schedule() because that enforces shutdown rules. // Don't delegate to schedule() because that enforces shutdown rules.
val newTask = AwaitIdleTask() val newTask = AwaitIdleTask()
if (scheduleAndDecide(newTask, 0L)) { if (scheduleAndDecide(newTask, 0L, recurrence = false)) {
taskRunner.kickCoordinator(this) taskRunner.kickCoordinator(this)
} }
return newTask.latch return newTask.latch
@@ -139,7 +139,7 @@ class TaskQueue internal constructor(
} }
/** Adds [task] to run in [delayNanos]. Returns true if the coordinator is impacted. */ /** Adds [task] to run in [delayNanos]. Returns true if the coordinator is impacted. */
internal fun scheduleAndDecide(task: Task, delayNanos: Long): Boolean { internal fun scheduleAndDecide(task: Task, delayNanos: Long, recurrence: Boolean): Boolean {
task.initQueue(this) task.initQueue(this)
val now = taskRunner.backend.nanoTime() val now = taskRunner.backend.nanoTime()
@@ -155,7 +155,10 @@ class TaskQueue internal constructor(
futureTasks.removeAt(existingIndex) // Already scheduled later: reschedule below! futureTasks.removeAt(existingIndex) // Already scheduled later: reschedule below!
} }
task.nextExecuteNanoTime = executeNanoTime task.nextExecuteNanoTime = executeNanoTime
taskLog(task, this) { "scheduled after ${formatDuration(executeNanoTime - now)}" } taskLog(task, this) {
if (recurrence) "run again after ${formatDuration(executeNanoTime - now)}"
else "scheduled after ${formatDuration(executeNanoTime - now)}"
}
// Insert in chronological order. Always compare deltas because nanoTime() is permitted to wrap. // Insert in chronological order. Always compare deltas because nanoTime() is permitted to wrap.
var insertAt = futureTasks.indexOfFirst { it.nextExecuteNanoTime - now > delayNanos } var insertAt = futureTasks.indexOfFirst { it.nextExecuteNanoTime - now > delayNanos }

4
okhttp/src/main/java/okhttp3/internal/concurrent/TaskRunner.kt
View File

@@ -41,7 +41,7 @@ import java.util.logging.Logger
class TaskRunner( class TaskRunner(
val backend: Backend val backend: Backend
) { ) {
private var nextQueueName = 1 private var nextQueueName = 10000
private var coordinatorWaiting = false private var coordinatorWaiting = false
private var coordinatorWakeUpAt = 0L private var coordinatorWakeUpAt = 0L
@@ -133,7 +133,7 @@ class TaskRunner(
busyQueues.remove(queue) busyQueues.remove(queue)
if (delayNanos != -1L && !cancelActiveTask && !queue.shutdown) { if (delayNanos != -1L && !cancelActiveTask && !queue.shutdown) {
queue.scheduleAndDecide(task, delayNanos) queue.scheduleAndDecide(task, delayNanos, recurrence = true)
} }
if (queue.futureTasks.isNotEmpty()) { if (queue.futureTasks.isNotEmpty()) {

64
okhttp/src/test/java/okhttp3/internal/concurrent/TaskLoggerTest.kt
View File

@@ -21,49 +21,49 @@ import org.junit.Test
class TaskLoggerTest { class TaskLoggerTest {
@Test fun formatTime() { @Test fun formatTime() {
/* ktlint-disable */ /* ktlint-disable */
assertThat(formatDuration(-3_499_999_999L)).isEqualTo("-3 s") assertThat(formatDuration(-3_499_999_999L)).isEqualTo(" -3 s ")
assertThat(formatDuration(-3_000_000_000L)).isEqualTo("-3 s") assertThat(formatDuration(-3_000_000_000L)).isEqualTo(" -3 s ")
assertThat(formatDuration(-2_500_000_000L)).isEqualTo("-3 s") assertThat(formatDuration(-2_500_000_000L)).isEqualTo(" -3 s ")
assertThat(formatDuration(-2_499_999_999L)).isEqualTo("-2 s") assertThat(formatDuration(-2_499_999_999L)).isEqualTo(" -2 s ")
assertThat(formatDuration(-1_500_000_000L)).isEqualTo("-2 s") assertThat(formatDuration(-1_500_000_000L)).isEqualTo(" -2 s ")
assertThat(formatDuration(-1_499_999_999L)).isEqualTo("-1 s") assertThat(formatDuration(-1_499_999_999L)).isEqualTo(" -1 s ")
assertThat(formatDuration(-1_000_000_000L)).isEqualTo("-1 s") assertThat(formatDuration(-1_000_000_000L)).isEqualTo(" -1 s ")
assertThat(formatDuration( -999_500_000L)).isEqualTo("-1 s") assertThat(formatDuration( -999_500_000L)).isEqualTo(" -1 s ")
assertThat(formatDuration( -999_499_999L)).isEqualTo("-999 ms") assertThat(formatDuration( -999_499_999L)).isEqualTo("-999 ms")
assertThat(formatDuration( -998_500_000L)).isEqualTo("-999 ms") assertThat(formatDuration( -998_500_000L)).isEqualTo("-999 ms")
assertThat(formatDuration( -998_499_999L)).isEqualTo("-998 ms") assertThat(formatDuration( -998_499_999L)).isEqualTo("-998 ms")
assertThat(formatDuration( -1_499_999L)).isEqualTo("-1 ms") assertThat(formatDuration( -1_499_999L)).isEqualTo(" -1 ms")
assertThat(formatDuration( -999_500L)).isEqualTo("-1 ms") assertThat(formatDuration( -999_500L)).isEqualTo(" -1 ms")
assertThat(formatDuration( -999_499L)).isEqualTo("-999 µs") assertThat(formatDuration( -999_499L)).isEqualTo("-999 µs")
assertThat(formatDuration( -998_500L)).isEqualTo("-999 µs") assertThat(formatDuration( -998_500L)).isEqualTo("-999 µs")
assertThat(formatDuration( -1_500L)).isEqualTo("-2 µs") assertThat(formatDuration( -1_500L)).isEqualTo(" -2 µs")
assertThat(formatDuration( -1_499L)).isEqualTo("-1 µs") assertThat(formatDuration( -1_499L)).isEqualTo(" -1 µs")
assertThat(formatDuration( -1_000L)).isEqualTo("-1 µs") assertThat(formatDuration( -1_000L)).isEqualTo(" -1 µs")
assertThat(formatDuration( -999L)).isEqualTo("-1 µs") assertThat(formatDuration( -999L)).isEqualTo(" -1 µs")
assertThat(formatDuration( -500L)).isEqualTo("-1 µs") assertThat(formatDuration( -500L)).isEqualTo(" -1 µs")
assertThat(formatDuration( -499L)).isEqualTo("0 µs") assertThat(formatDuration( -499L)).isEqualTo(" 0 µs")
assertThat(formatDuration( 3_499_999_999L)).isEqualTo("3 s") assertThat(formatDuration( 3_499_999_999L)).isEqualTo(" 3 s ")
assertThat(formatDuration( 3_000_000_000L)).isEqualTo("3 s") assertThat(formatDuration( 3_000_000_000L)).isEqualTo(" 3 s ")
assertThat(formatDuration( 2_500_000_000L)).isEqualTo("3 s") assertThat(formatDuration( 2_500_000_000L)).isEqualTo(" 3 s ")
assertThat(formatDuration( 2_499_999_999L)).isEqualTo("2 s") assertThat(formatDuration( 2_499_999_999L)).isEqualTo(" 2 s ")
assertThat(formatDuration( 1_500_000_000L)).isEqualTo("2 s") assertThat(formatDuration( 1_500_000_000L)).isEqualTo(" 2 s ")
assertThat(formatDuration( 1_499_999_999L)).isEqualTo("1 s") assertThat(formatDuration( 1_499_999_999L)).isEqualTo(" 1 s ")
assertThat(formatDuration( 1_000_000_000L)).isEqualTo("1 s") assertThat(formatDuration( 1_000_000_000L)).isEqualTo(" 1 s ")
assertThat(formatDuration( 999_500_000L)).isEqualTo("1 s") assertThat(formatDuration( 999_500_000L)).isEqualTo(" 1 s ")
assertThat(formatDuration( 999_499_999L)).isEqualTo("999 ms") assertThat(formatDuration( 999_499_999L)).isEqualTo("999 ms")
assertThat(formatDuration( 998_500_000L)).isEqualTo("999 ms") assertThat(formatDuration( 998_500_000L)).isEqualTo("999 ms")
assertThat(formatDuration( 998_499_999L)).isEqualTo("998 ms") assertThat(formatDuration( 998_499_999L)).isEqualTo("998 ms")
assertThat(formatDuration( 1_499_999L)).isEqualTo("1 ms") assertThat(formatDuration( 1_499_999L)).isEqualTo(" 1 ms")
assertThat(formatDuration( 999_500L)).isEqualTo("1 ms") assertThat(formatDuration( 999_500L)).isEqualTo(" 1 ms")
assertThat(formatDuration( 999_499L)).isEqualTo("999 µs") assertThat(formatDuration( 999_499L)).isEqualTo("999 µs")
assertThat(formatDuration( 998_500L)).isEqualTo("999 µs") assertThat(formatDuration( 998_500L)).isEqualTo("999 µs")
assertThat(formatDuration( 1_500L)).isEqualTo("2 µs") assertThat(formatDuration( 1_500L)).isEqualTo(" 2 µs")
assertThat(formatDuration( 1_499L)).isEqualTo("1 µs") assertThat(formatDuration( 1_499L)).isEqualTo(" 1 µs")
assertThat(formatDuration( 1_000L)).isEqualTo("1 µs") assertThat(formatDuration( 1_000L)).isEqualTo(" 1 µs")
assertThat(formatDuration( 999L)).isEqualTo("1 µs") assertThat(formatDuration( 999L)).isEqualTo(" 1 µs")
assertThat(formatDuration( 500L)).isEqualTo("1 µs") assertThat(formatDuration( 500L)).isEqualTo(" 1 µs")
assertThat(formatDuration( 499L)).isEqualTo("0 µs") assertThat(formatDuration( 499L)).isEqualTo(" 0 µs")
/* ktlint-enable */ /* ktlint-enable */
} }
} }

186
okhttp/src/test/java/okhttp3/internal/concurrent/TaskRunnerTest.kt
View File

@@ -49,9 +49,9 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 finished in 0 µs: task" "FINE: Q10000 finished run in 0 µs: task"
) )
} }
@@ -80,15 +80,15 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 scheduled after 50 µs: task", "FINE: Q10000 run again after 50 µs: task",
"FINE: Q1 finished in 0 µs: task", "FINE: Q10000 finished run in 0 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 scheduled after 150 µs: task", "FINE: Q10000 run again after 150 µs: task",
"FINE: Q1 finished in 0 µs: task", "FINE: Q10000 finished run in 0 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 finished in 0 µs: task" "FINE: Q10000 finished run in 0 µs: task"
) )
} }
@@ -119,13 +119,13 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 scheduled after 50 µs: task", "FINE: Q10000 scheduled after 50 µs: task",
"FINE: Q1 already scheduled: task", "FINE: Q10000 already scheduled : task",
"FINE: Q1 finished in 0 µs: task", "FINE: Q10000 finished run in 0 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 finished in 0 µs: task" "FINE: Q10000 finished run in 0 µs: task"
) )
} }
@@ -156,13 +156,13 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 scheduled after 200 µs: task", "FINE: Q10000 scheduled after 200 µs: task",
"FINE: Q1 scheduled after 50 µs: task", "FINE: Q10000 run again after 50 µs: task",
"FINE: Q1 finished in 0 µs: task", "FINE: Q10000 finished run in 0 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 finished in 0 µs: task" "FINE: Q10000 finished run in 0 µs: task"
) )
} }
@@ -182,8 +182,8 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 canceled: task" "FINE: Q10000 canceled : task"
) )
} }
@@ -209,9 +209,9 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 finished in 0 µs: task" "FINE: Q10000 finished run in 0 µs: task"
) )
} }
@@ -231,9 +231,9 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 finished in 0 µs: task" "FINE: Q10000 finished run in 0 µs: task"
) )
} }
@@ -252,9 +252,9 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 finished in 0 µs: task" "FINE: Q10000 finished run in 0 µs: task"
) )
} }
@@ -280,12 +280,12 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 scheduled after 50 µs: task", "FINE: Q10000 run again after 50 µs: task",
"FINE: Q1 finished in 0 µs: task", "FINE: Q10000 finished run in 0 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 finished in 0 µs: task" "FINE: Q10000 finished run in 0 µs: task"
) )
} }
@@ -305,8 +305,8 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 canceled: task" "FINE: Q10000 canceled : task"
) )
} }
@@ -332,9 +332,9 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 finished in 0 µs: task" "FINE: Q10000 finished run in 0 µs: task"
) )
} }
@@ -365,15 +365,15 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task one", "FINE: Q10000 scheduled after 100 µs: task one",
"FINE: Q1 scheduled after 100 µs: task two", "FINE: Q10000 scheduled after 100 µs: task two",
"FINE: Q1 scheduled after 100 µs: task three", "FINE: Q10000 scheduled after 100 µs: task three",
"FINE: Q1 starting: task one", "FINE: Q10000 starting : task one",
"FINE: Q1 finished in 0 µs: task one", "FINE: Q10000 finished run in 0 µs: task one",
"FINE: Q1 starting: task two", "FINE: Q10000 starting : task two",
"FINE: Q1 finished in 0 µs: task two", "FINE: Q10000 finished run in 0 µs: task two",
"FINE: Q1 starting: task three", "FINE: Q10000 starting : task three",
"FINE: Q1 finished in 0 µs: task three" "FINE: Q10000 finished run in 0 µs: task three"
) )
} }
@@ -404,15 +404,15 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task one", "FINE: Q10000 scheduled after 100 µs: task one",
"FINE: Q2 scheduled after 100 µs: task two", "FINE: Q10001 scheduled after 100 µs: task two",
"FINE: Q3 scheduled after 100 µs: task three", "FINE: Q10002 scheduled after 100 µs: task three",
"FINE: Q1 starting: task one", "FINE: Q10000 starting : task one",
"FINE: Q1 finished in 0 µs: task one", "FINE: Q10000 finished run in 0 µs: task one",
"FINE: Q2 starting: task two", "FINE: Q10001 starting : task two",
"FINE: Q2 finished in 0 µs: task two", "FINE: Q10001 finished run in 0 µs: task two",
"FINE: Q3 starting: task three", "FINE: Q10002 starting : task three",
"FINE: Q3 finished in 0 µs: task three" "FINE: Q10002 finished run in 0 µs: task three"
) )
} }
@@ -429,8 +429,8 @@ class TaskRunnerTest {
assertThat(redQueue.scheduledTasks.toString()).isEqualTo("[task one, task two]") assertThat(redQueue.scheduledTasks.toString()).isEqualTo("[task one, task two]")
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task one", "FINE: Q10000 scheduled after 100 µs: task one",
"FINE: Q1 scheduled after 200 µs: task two" "FINE: Q10000 scheduled after 200 µs: task two"
) )
} }
@@ -476,15 +476,15 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task one", "FINE: Q10000 scheduled after 100 µs: task one",
"FINE: Q1 scheduled after 200 µs: task two", "FINE: Q10000 scheduled after 200 µs: task two",
"FINE: Q1 starting: task one", "FINE: Q10000 starting : task one",
"FINE: Q1 scheduled after 200 µs: task one", "FINE: Q10000 scheduled after 200 µs: task one",
"FINE: Q1 finished in 0 µs: task one", "FINE: Q10000 finished run in 0 µs: task one",
"FINE: Q1 starting: task two", "FINE: Q10000 starting : task two",
"FINE: Q1 finished in 0 µs: task two", "FINE: Q10000 finished run in 0 µs: task two",
"FINE: Q1 starting: task one", "FINE: Q10000 starting : task one",
"FINE: Q1 finished in 0 µs: task one" "FINE: Q10000 finished run in 0 µs: task one"
) )
} }
@@ -514,12 +514,12 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task one", "FINE: Q10000 scheduled after 100 µs: task one",
"FINE: Q2 scheduled after 200 µs: task two", "FINE: Q10001 scheduled after 200 µs: task two",
"FINE: Q1 starting: task one", "FINE: Q10000 starting : task one",
"FINE: Q1 finished in 0 µs: task one", "FINE: Q10000 finished run in 0 µs: task one",
"FINE: Q2 starting: task two", "FINE: Q10001 starting : task two",
"FINE: Q2 finished in 0 µs: task two" "FINE: Q10001 finished run in 0 µs: task two"
) )
} }
@@ -534,9 +534,9 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 0 µs: lucky task", "FINE: Q10000 scheduled after 0 µs: lucky task",
"FINE: Q1 starting: lucky task", "FINE: Q10000 starting : lucky task",
"FINE: Q1 finished in 0 µs: lucky task" "FINE: Q10000 finished run in 0 µs: lucky task"
) )
} }
@@ -556,8 +556,8 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 canceled: task" "FINE: Q10000 canceled : task"
) )
} }
@@ -583,9 +583,9 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 scheduled after 100 µs: task", "FINE: Q10000 scheduled after 100 µs: task",
"FINE: Q1 starting: task", "FINE: Q10000 starting : task",
"FINE: Q1 finished in 0 µs: task" "FINE: Q10000 finished run in 0 µs: task"
) )
} }
@@ -599,7 +599,7 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 schedule canceled (queue is shutdown): task" "FINE: Q10000 schedule canceled (queue is shutdown): task"
) )
} }
@@ -619,7 +619,7 @@ class TaskRunnerTest {
taskFaker.assertNoMoreTasks() taskFaker.assertNoMoreTasks()
assertThat(testLogHandler.takeAll()).containsExactly( assertThat(testLogHandler.takeAll()).containsExactly(
"FINE: Q1 schedule failed (queue is shutdown): task" "FINE: Q10000 schedule failed (queue is shutdown): task"
) )
} }