Nitrite Failing on Second Write to DB

[nitrite]

Nitrite Failing on Second Write to DB

[lonpalmer]

Just a note, I reported this issue earlier but it was closed as un able to reproduce. I'm reproducing it 100% now.

[anidotnet]

Based on your description I have created below example:

fun main(args: Array<String>) {    
    for (i in 0..5) {
        saveReport(IIotReport())
    }
}

val DB_PATH: String = "iotdb.database"
val database : Nitrite by lazy { makeOrOpenDb() }

private fun makeOrOpenDb(): Nitrite {
    val db = Nitrite.builder().compressed().filePath(DB_PATH).openOrCreate()
    return db
}

fun saveReport(report: IIotReport) {
    database.getCollection("report").insert(makeDocument(report))
}

private fun makeDocument(report: IIotReport): Document {
    val doc = Document()
    doc.put("type", report.type.toString())
    doc.put("date", report.date.time)
    doc.put("sn", report.serialNumber.toString())
    doc.put("rec", report)
    return doc
}

val counter = AtomicInteger(1)

class IIotReport {
    var type: String = "test report ${counter.getAndIncrement()}"
    var date: Date = Date()
    var serialNumber: Long = System.currentTimeMillis()
}

but I am still unable to reproduce. It is writing data properly for me. Can you please work on the code I provided here and make it reproducible? If you can share your code privately that is also okay with me. Somehow, I need to reproduce it.

Please provide your environment details also - like OS, JVM version etc.

[lonpalmer]

This works fine on my windows 10 development work station. It fails, however on the linux production environment machine.

I could send the created database to you if that would help you understand what's going on.

[anidotnet]

My own machine is also Ubuntu 17.10, 64bit. The problem is not with database file I think. Can you create a heap dump and check what is going on? According to the error message there might be an OOM happening. Heap dump might help you to debug it.

You can view the database yourself, using Nitrite Explorer.

[lonpalmer]

Memory use for the java process is very, very low. I can’t imagine it’s OOM. I’ll get you a heap dump ASAP. NOTE this did happen on my Windows machine in the past and the way I got cleared the problem was to delete the database and recreate it.

…

________________________________ From: Anindya Chatterjee <[email protected]> Sent: Sunday, October 29, 2017 1:50:09 PM To: dizitart/nitrite-database Cc: lonpalmer; Author Subject: Re: [dizitart/nitrite-database] Nitrite Failing on Second Write to DB (#31) My own machine is also Ubuntu 17.10, 64bit. The problem is not with database file I think. Can you create a heap dump and check what is going on? According to the error message there might be an OOM happening. Heap dump might help you to debug it. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub<https://nam02.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fdizitart%2Fnitrite-database%2Fissues%2F31%23issuecomment-340284888&data=02%7C01%7Clonpalmer%40outlook.com%7C6737e63e11a44d5ce7e408d51efeaaa4%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C636449001483684125&sdata=hhbI%2Fn0xQ2AbrTJnwO2jjJiTmsvXcqP5plaBFIpCuHc%3D&reserved=0>, or mute the thread<https://nam02.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAMjRC-mvK5baJNzrYyBPl_FwjfYOUklBks5sxMjhgaJpZM4QKVwi&data=02%7C01%7Clonpalmer%40outlook.com%7C6737e63e11a44d5ce7e408d51efeaaa4%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C636449001483840371&sdata=w0tlHRRVkkIjW9wR2TyXAGGVmGhOthRNufdrqrdvZ4c%3D&reserved=0>.

[lonpalmer]

I looked at the Heap Dump and it was very small. 3.5MB for the entire application. Nothing seemed out of the ordinary. I'm happy to send it to you if you wouldn't mind looking at it.

I have some more information for you:

1. If I write to the database quickly (2 inserts in a couple of seconds) both inserts are successful. Then when the third insert takes more time (approx. 10s) it fails. It's like some process in Nitrite is closing the DB. Perhaps the process that writes memory cached data to the file.

[anidotnet]

With your last description (delay of 10 sec.) I was able to reproduce the issue. The culprit is this line:

doc.put(DB_COL_REC, report)

The reason is, you are storing a java/kotlin object inside a document. Java mandates, you mark any object withSerializable if you want to binary serialize it, or you implement readObject() and writeObject(). If you don't, the object won't be serialized and a NotSerializableException will be thrown. Your report object does not implement Serializable and that's why it is throwing an exception while storing it, but MVStore library is somehow eating the exception and not bubbling it up the stack. This exception is panicking and closing the MVStore prematurely. That's why in the next write you see this exception as "store is closed".

The reason you are not able to see this error while writing in close succession is, MVStore writes data in a background thread after certain interval. By the time the write loop completes, MVStore does not writes data to disk, so you are not seeing this error. But if you introduce delay in writes, the MVStore background thread kicks in and try to writes data whatever is in the buffer. When it fails, it panics and closes the store and failing the next write.

So the remedy is - either implement Serializable for your report class, or convert your report class to a Document of primitive types, or use ObjectRepository<IIotReport> instead of NitriteCollection. ObjectRepository will convert your report class into a Document and takes care of the serialization.

Meantime, as MVStore is eating up the exception, I'll put a check of Serializable object in the code, so that user get's a proper error message.

[lonpalmer]

Thank you, Anindya. That makes perfect sense. I'll move to an ObjectRepository. Regards and thanks for the help! Lon Palmer

…

________________________________ From: Anindya Chatterjee <[email protected]> Sent: Tuesday, October 31, 2017 12:35:47 AM To: dizitart/nitrite-database Cc: lonpalmer; Author Subject: Re: [dizitart/nitrite-database] Nitrite Failing on Second Write to DB (#31) With your last description (delay of 10 sec.) I was able to reproduce the issue. The culprit is this line: doc.put(DB_COL_REC, report) The reason is, you are storing a java/kotlin object inside a document. Java mandates, you mark any object withSerializable if you want to binary serialize it, or you implement readObject() and writeObject(). If you don't, the object won't be serialized and a NotSerializableException will be thrown. Your report object does not implement Serializable and that's why it is throwing an exception while storing it, but MVStore library is somehow eating the exception and not bubbling it up the stack. This exception is panicking and closing the MVStore prematurely. That's why in the next write you see this exception as "store is closed". The reason you are not able to see this error while writing in close succession is, MVStore writes data in a background thread after certain interval. By the time the write loop completes, MVStore does not writes data to disk, so you are not seeing this error. But if you introduce delay in writes, the MVStore background thread kicks in and try to writes data whatever is in the buffer. When it fails, it panics and closes the store and failing the next write. So the remedy is - either implement Serializable for your report class, or convert your report class to a Document of primitive types, or use ObjectRepository<IIotReport> instead of NitriteCollection. ObjectRepository will convert your report class into a Document and takes care of the serialization. Meantime, as MVStore is eating up the exception, I'll put a check of Serializable object in the code, so that user get's a proper error message. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub<https://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fdizitart%2Fnitrite-database%2Fissues%2F31%23issuecomment-340657558&data=02%7C01%7Clonpalmer%40outlook.com%7C8a5829001ec54d3fa06608d52018dbb8%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C636450213486524508&sdata=o2Pe%2BZtYXwYR1NLNx172w%2FQpdYUMJ3BvtWJpeKZxPi0%3D&reserved=0>, or mute the thread<https://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAMjRC3aKq-gVvom5493irYGkMJLMDV1-ks5sxqOjgaJpZM4QKVwi&data=02%7C01%7Clonpalmer%40outlook.com%7C8a5829001ec54d3fa06608d52018dbb8%7C84df9e7fe9f640afb435aaaaaaaaaaaa%7C1%7C0%7C636450213486524508&sdata=8JH4YM2%2B8w4SsidaYcx%2FG0vlfflFnxMmTv5Ub5CPdbI%3D&reserved=0>.