From a32b70c316d724b8649ffe8aa0e4ba45cbf0a15d Mon Sep 17 00:00:00 2001 From: Fabrice Lecomte Date: Thu, 18 Jul 2019 00:02:26 +0200 Subject: [PATCH] feature #10: log Query --- .idea/postgres-json.iml | 4 +- .../fr/postgresjson/connexion/Connection.kt | 47 ++++++++++++++----- .../fr/postgresjson/connexion/Requester.kt | 13 +++-- .../fr/postgresjson/migration/Migrations.kt | 18 +++---- .../kotlin/fr/postgresjson/migration/Query.kt | 4 +- .../fr/postgresjson/stopwatch/Stopwatch.kt | 8 ++++ .../kotlin/fr/postgresjson/ConnectionTest.kt | 15 +++--- .../kotlin/fr/postgresjson/RequesterTest.kt | 14 ++---- src/test/resources/logback.xml | 10 ++-- 9 files changed, 79 insertions(+), 54 deletions(-) create mode 100644 src/main/kotlin/fr/postgresjson/stopwatch/Stopwatch.kt diff --git a/.idea/postgres-json.iml b/.idea/postgres-json.iml index d6ebd48..e4ca15c 100644 --- a/.idea/postgres-json.iml +++ b/.idea/postgres-json.iml @@ -2,7 +2,9 @@ - + + + diff --git a/src/main/kotlin/fr/postgresjson/connexion/Connection.kt b/src/main/kotlin/fr/postgresjson/connexion/Connection.kt index 78d84b5..db9478d 100644 --- a/src/main/kotlin/fr/postgresjson/connexion/Connection.kt +++ b/src/main/kotlin/fr/postgresjson/connexion/Connection.kt @@ -20,8 +20,9 @@ interface Executable { fun > select(sql: String, typeReference: TypeReference>, values: List = emptyList()): List fun > select(sql: String, typeReference: TypeReference>, values: Map): List fun > select(sql: String, page: Int, limit: Int, typeReference: TypeReference>, values: Map): Paginated - fun exec(sql: String, values: List = emptyList()): CompletableFuture - fun exec(sql: String, values: Map): CompletableFuture + fun exec(sql: String, values: List = emptyList()): QueryResult + fun exec(sql: String, values: Map): QueryResult + fun sendQuery(sql: String): QueryResult } class Connection( @@ -35,7 +36,7 @@ class Connection( private val serializer = Serializer() private val logger: Logger? by LoggerDelegate() - fun connect(): ConnectionPool { + internal fun connect(): ConnectionPool { if (!::connection.isInitialized || !connection.isConnected()) { connection = PostgreSQLConnectionBuilder.createConnectionPool( "jdbc:postgresql://$host:$port/$database?user=$username&password=$password" @@ -47,8 +48,8 @@ class Connection( fun inTransaction(f: (Connection) -> CompletableFuture) = connect().inTransaction(f) override fun > select(sql: String, typeReference: TypeReference, values: List): R? { - val future = connect().sendPreparedStatement(sql, compileArgs(values)) - val json = future.get().rows[0].getString(0) + val result = exec(sql, compileArgs(values)) + val json = result.rows[0].getString(0) return if (json === null) { null } else { @@ -69,8 +70,8 @@ class Connection( select(sql, object: TypeReference() {}, values) override fun > select(sql: String, typeReference: TypeReference>, values: List): List { - val future = connect().sendPreparedStatement(sql, compileArgs(values)) - val json = future.get().rows[0].getString(0) + val result = exec(sql, compileArgs(values)) + val json = result.rows[0].getString(0) return if (json === null) { listOf>() as List } else { @@ -94,7 +95,7 @@ class Connection( .plus("limit" to limit) val line = replaceArgs(sql, newValues) { - connect().sendPreparedStatement(this.sql, compileArgs(this.parameters)).get().rows[0] + exec(this.sql, compileArgs(this.parameters)).rows[0] } return line.run { @@ -134,17 +135,24 @@ class Connection( inline fun > select(sql: String, values: Map): List = select(sql, object: TypeReference>() {}, values) - override fun exec(sql: String, values: List): CompletableFuture { - logger?.debug(sql, values) - return connect().sendPreparedStatement(sql, compileArgs(values)) + override fun exec(sql: String, values: List): QueryResult { + return stopwatchQuery(sql, values) { + connect().sendPreparedStatement(sql, compileArgs(values)).join() + } } - override fun exec(sql: String, values: Map): CompletableFuture { + override fun exec(sql: String, values: Map): QueryResult { return replaceArgs(sql, values) { exec(this.sql, this.parameters) } } + override fun sendQuery(sql: String): QueryResult { + return stopwatchQuery(sql) { + connect().sendQuery(sql).join() + } + } + private fun compileArgs(values: List): List { return values.map { if (it is EntityI<*>) { @@ -174,6 +182,21 @@ class Connection( } data class ParametersQuery(val sql: String, val parameters: List) + + private fun stopwatchQuery(sql: String, values: List = emptyList(), callback: () -> T): T { + val sqlForLog = "\n"+sql.prependIndent() + try { + val start = System.currentTimeMillis() + val result = callback() + val duration = (System.currentTimeMillis() - start) + logger?.debug("$duration ms for query: $sqlForLog", values) + return result + } catch (e: Throwable) { + logger?.info("Query Error: $sqlForLog", e) + throw e + } + + } } data class Paginated>( diff --git a/src/main/kotlin/fr/postgresjson/connexion/Requester.kt b/src/main/kotlin/fr/postgresjson/connexion/Requester.kt index 0992f6c..ff1599d 100644 --- a/src/main/kotlin/fr/postgresjson/connexion/Requester.kt +++ b/src/main/kotlin/fr/postgresjson/connexion/Requester.kt @@ -4,7 +4,6 @@ import com.fasterxml.jackson.core.type.TypeReference import com.github.jasync.sql.db.QueryResult import fr.postgresjson.entity.EntityI import java.io.File -import java.util.concurrent.CompletableFuture import fr.postgresjson.definition.Function as DefinitionFunction class Requester( @@ -109,11 +108,11 @@ class Requester( inline fun > select(page: Int, limit: Int, values: Map = emptyMap()): Paginated = select(page, limit, object: TypeReference>() {}, values) - override fun exec(values: List): CompletableFuture { + override fun exec(values: List): QueryResult { return connection.exec(sql, values) } - override fun exec(values: Map): CompletableFuture { + override fun exec(values: Map): QueryResult { return connection.exec(sql, values) } } @@ -185,14 +184,14 @@ class Requester( inline fun > select(page: Int, limit: Int, values: Map = emptyMap()): Paginated = select(page, limit, object: TypeReference>() {}, values) - override fun exec(values: List): CompletableFuture { + override fun exec(values: List): QueryResult { val args = compileArgs(values) val sql = "SELECT * FROM ${definition.name} ($args)" return connection.exec(sql, values) } - override fun exec(values: Map): CompletableFuture { + override fun exec(values: Map): QueryResult { val args = compileArgs(values) val sql = "SELECT * FROM ${definition.name} ($args)" @@ -239,8 +238,8 @@ class Requester( fun > select(page: Int, limit: Int, typeReference: TypeReference>, values: Map): Paginated - fun exec(values: List = emptyList()): CompletableFuture - fun exec(values: Map): CompletableFuture + fun exec(values: List = emptyList()): QueryResult + fun exec(values: Map): QueryResult } class RequesterFactory( diff --git a/src/main/kotlin/fr/postgresjson/migration/Migrations.kt b/src/main/kotlin/fr/postgresjson/migration/Migrations.kt index 7d63be3..915a82a 100644 --- a/src/main/kotlin/fr/postgresjson/migration/Migrations.kt +++ b/src/main/kotlin/fr/postgresjson/migration/Migrations.kt @@ -154,10 +154,10 @@ data class Migrations private constructor( private fun initDB() { if (!initialized) { File(this::class.java.getResource("/sql/migration/createHistoryShema.sql").toURI()).let { - connection.connect().sendQuery(it.readText()).join() + connection.sendQuery(it.readText()) } File(this::class.java.getResource("/sql/migration/createFunctionShema.sql").toURI()).let { - connection.connect().sendQuery(it.readText()).join() + connection.sendQuery(it.readText()) } initialized = true } @@ -165,7 +165,7 @@ data class Migrations private constructor( private fun lock() { File(this::class.java.getResource("/sql/migration/lockMigrationTables.sql").toURI()).let { - connection.connect().sendQuery(it.readText()).join() + connection.sendQuery(it.readText()) } } @@ -221,8 +221,8 @@ data class Migrations private constructor( fun run(): Map, Status> { val list: MutableMap, Status> = mutableMapOf() - connection.connect().apply { - sendQuery("BEGIN").join() + connection.apply { + sendQuery("BEGIN") lock() up().map { list[Pair(it.key, Direction.UP)] = it.value @@ -230,7 +230,7 @@ data class Migrations private constructor( down(true).map { list[Pair(it.key, Direction.DOWN)] = it.value } - sendQuery("COMMIT").join() + sendQuery("COMMIT") } return list.toMap() @@ -242,15 +242,15 @@ data class Migrations private constructor( private fun runTest(): Map, Status> { val list: MutableMap, Status> = mutableMapOf() - connection.connect().apply { - sendQuery("BEGIN").join() + connection.apply { + sendQuery("BEGIN") up().map { list[Pair(it.key, Direction.UP)] = it.value } down(true).map { list[Pair(it.key, Direction.DOWN)] = it.value } - sendQuery("ROLLBACK").join() + sendQuery("ROLLBACK") } return list.toMap() diff --git a/src/main/kotlin/fr/postgresjson/migration/Query.kt b/src/main/kotlin/fr/postgresjson/migration/Query.kt index 3b13268..bc3ec68 100644 --- a/src/main/kotlin/fr/postgresjson/migration/Query.kt +++ b/src/main/kotlin/fr/postgresjson/migration/Query.kt @@ -16,7 +16,7 @@ data class Query( override var doExecute: Action? = null override fun up(): Migration.Status { - connection.exec(up).join() + connection.exec(up) File(this::class.java.getResource("/sql/migration/insertHistory.sql").toURI()).let { connection.selectOne(it.readText(), listOf(name, up, down))?.let { query -> @@ -29,7 +29,7 @@ data class Query( } override fun down(): Migration.Status { - connection.exec(down).join() + connection.exec(down) File(this::class.java.getResource("/sql/migration/deleteHistory.sql").toURI()).let { connection.exec(it.readText(), listOf(name)) diff --git a/src/main/kotlin/fr/postgresjson/stopwatch/Stopwatch.kt b/src/main/kotlin/fr/postgresjson/stopwatch/Stopwatch.kt new file mode 100644 index 0000000..51244f2 --- /dev/null +++ b/src/main/kotlin/fr/postgresjson/stopwatch/Stopwatch.kt @@ -0,0 +1,8 @@ +package fr.postgresjson.stopwatch + +fun elapse(callback: (start: Long) -> T, after: (elapse: Long) -> Unit): T { + val start = System.currentTimeMillis() + val result = callback(start) + after(System.currentTimeMillis() - start) + return result +} diff --git a/src/test/kotlin/fr/postgresjson/ConnectionTest.kt b/src/test/kotlin/fr/postgresjson/ConnectionTest.kt index 8b708d7..9c72b10 100644 --- a/src/test/kotlin/fr/postgresjson/ConnectionTest.kt +++ b/src/test/kotlin/fr/postgresjson/ConnectionTest.kt @@ -1,10 +1,10 @@ package fr.postgresjson -import com.github.jasync.sql.db.util.isCompleted import fr.postgresjson.connexion.Connection import fr.postgresjson.connexion.Paginated import fr.postgresjson.entity.IdEntity import org.junit.Assert.* +import org.junit.jupiter.api.Assertions import org.junit.jupiter.api.BeforeEach import org.junit.jupiter.api.Test import org.junit.jupiter.api.TestInstance @@ -41,7 +41,7 @@ class ConnectionTest(): TestAbstract() { from test2 t JOIN test t2 ON t.test_id = t2.id ) j; - """ + """.trimIndent() ) assertNotNull(objs) assertTrue(objs is List) @@ -71,9 +71,8 @@ class ConnectionTest(): TestAbstract() { @Test fun callExec() { val o = ObjTest("myName") - val future = connection.exec("select json_build_object('id', 1, 'name', ?::json->>'name')", listOf(o)) - future.join() - assertTrue(future.isCompleted) + val result = connection.exec("select json_build_object('id', 1, 'name', ?::json->>'name')", listOf(o)) + Assertions.assertEquals(1, result.rowsAffected) } @Test @@ -107,9 +106,9 @@ class ConnectionTest(): TestAbstract() { """.trimIndent(), params ) - assertEquals(result[0]!!.first, "ff") - assertEquals(result[0]!!.seconde, "sec") - assertEquals(result[0]!!.third, 123) + assertEquals(result[0].first, "ff") + assertEquals(result[0].seconde, "sec") + assertEquals(result[0].third, 123) } @Test diff --git a/src/test/kotlin/fr/postgresjson/RequesterTest.kt b/src/test/kotlin/fr/postgresjson/RequesterTest.kt index 60f88cb..a430691 100644 --- a/src/test/kotlin/fr/postgresjson/RequesterTest.kt +++ b/src/test/kotlin/fr/postgresjson/RequesterTest.kt @@ -1,16 +1,12 @@ package fr.postgresjson -import com.github.jasync.sql.db.QueryResult -import com.github.jasync.sql.db.util.isCompleted import fr.postgresjson.connexion.Paginated import fr.postgresjson.connexion.Requester import fr.postgresjson.entity.IdEntity import org.junit.Assert -import org.junit.jupiter.api.Assertions import org.junit.jupiter.api.Assertions.assertEquals import org.junit.jupiter.api.Test import java.io.File -import java.util.concurrent.CompletableFuture class RequesterTest: TestAbstract() { class ObjTest(var name:String): IdEntity(1) @@ -42,25 +38,23 @@ class RequesterTest: TestAbstract() { @Test fun `call exec on query`() { val resources = File(this::class.java.getResource("/sql/query").toURI()) - val future: CompletableFuture = Requester(getConnextion()) + val result = Requester(getConnextion()) .addQuery(resources) .getQuery("Test/selectOne") .exec() - future.join() - Assertions.assertTrue(future.isCompleted) + assertEquals(1, result.rowsAffected) } @Test fun `call exec on function`() { val resources = File(this::class.java.getResource("/sql/function").toURI()) - val future: CompletableFuture = Requester(getConnextion()) + val result = Requester(getConnextion()) .addFunction(resources) .getFunction("test_function") .exec(listOf("test", "plip")) - future.join() - Assertions.assertTrue(future.isCompleted) + assertEquals(1, result.rowsAffected) } @Test diff --git a/src/test/resources/logback.xml b/src/test/resources/logback.xml index ca7a864..2b14545 100644 --- a/src/test/resources/logback.xml +++ b/src/test/resources/logback.xml @@ -4,23 +4,23 @@ %d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n - + ${LOG_DIR}/query.log true - %d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n + %d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n ${LOG_DIR}/other.log true - %d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n + %d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n - + @@ -28,7 +28,7 @@ - + \ No newline at end of file