Could not free space for pending write

[gadeyne.bram]

Hi,

I'm currently using Teiid to copy billions of rows from different sources to a Microsoft SqlServer  database. The records are related to patient files.

I'm doiing this using a small Java program that uses a JDBC connection to execute the desired statements (copying each time some ten thousands of lines). The statements are virtual procedures who are called in teiid. So I assume that when a procedure ends and the statement is closed, all related resources like temporary tables etc. are released. The program closes statements for each command and connections when a patient is complete.

After a lot of data is transfered (approximately 300 patient files or about 100 million lines) I sometimes get errors like this one:

2018-06-20 13:27:29,876 ERROR [org.teiid.BUFFER_MGR] (Worker16_QueryProcessorQueue1390153) 9FtM+9TQiuKE TEIID30002 Error persisting, attempts to read 4,805,248 992,126 later will result in an exception. : java.lang.AssertionError: Could not free space for pending write

        at org.teiid.common.buffer.impl.BufferFrontedFileStoreCache.evictFromMemoryBuffer(BufferFrontedFileStoreCache.java:1164)

        at org.teiid.common.buffer.impl.BufferFrontedFileStoreCache$InodeBlockManager.nextBlock(BufferFrontedFileStoreCache.java:246)

        at org.teiid.common.buffer.impl.BufferFrontedFileStoreCache$InodeBlockManager.getOrUpdateDataBlockIndex(BufferFrontedFileStoreCache.java:201)

        at org.teiid.common.buffer.impl.BufferFrontedFileStoreCache$InodeBlockManager.allocateBlock(BufferFrontedFileStoreCache.java:348)

        at org.teiid.common.buffer.impl.BlockOutputStream.newBuffer(BlockOutputStream.java:51)

        at org.teiid.common.buffer.impl.ExtensibleBufferedOutputStream.ensureBuffer(ExtensibleBufferedOutputStream.java:51)

        at org.teiid.common.buffer.impl.ExtensibleBufferedOutputStream.write(ExtensibleBufferedOutputStream.java:57)

        at java.io.ObjectOutputStream$BlockDataOutputStream.drain(ObjectOutputStream.java:1877)

        at java.io.ObjectOutputStream$BlockDataOutputStream.write(ObjectOutputStream.java:1808)

        at java.io.DataOutputStream.writeInt(DataOutputStream.java:200)

        at java.io.ObjectOutputStream$BlockDataOutputStream.writeInt(ObjectOutputStream.java:1943)

        at java.io.ObjectOutputStream.writeInt(ObjectOutputStream.java:797)

        at org.teiid.client.BatchSerializer$IntColumnSerializer.writeObject(BatchSerializer.java:559)

        at org.teiid.client.BatchSerializer$ColumnSerializer.writeColumn(BatchSerializer.java:530)

        at org.teiid.client.BatchSerializer.writeBatch(BatchSerializer.java:863)

        at org.teiid.client.BatchSerializer.writeBatch(BatchSerializer.java:839)

        at org.teiid.common.buffer.impl.BufferManagerImpl$BatchManagerImpl.serialize(BufferManagerImpl.java:332)

        at org.teiid.common.buffer.impl.BufferManagerImpl$BatchManagerImpl.serialize(BufferManagerImpl.java:187)

        at org.teiid.common.buffer.impl.BufferFrontedFileStoreCache.add(BufferFrontedFileStoreCache.java:664)

        at org.teiid.common.buffer.impl.BufferManagerImpl.evict(BufferManagerImpl.java:1034)

        at org.teiid.common.buffer.impl.BufferManagerImpl.doEvictions(BufferManagerImpl.java:997)

        at org.teiid.common.buffer.impl.BufferManagerImpl.persistBatchReferences(BufferManagerImpl.java:955)

        at org.teiid.common.buffer.impl.BufferManagerImpl.addMemoryEntry(BufferManagerImpl.java:1144)

        at org.teiid.common.buffer.impl.BufferManagerImpl.fastGet(BufferManagerImpl.java:1104)

        at org.teiid.common.buffer.impl.BufferManagerImpl$BatchManagerImpl.getBatch(BufferManagerImpl.java:359)

        at org.teiid.common.buffer.SPage.getValues(SPage.java:234)

        at org.teiid.common.buffer.SPage.search(SPage.java:135)

        at org.teiid.common.buffer.STree.find(STree.java:247)

        at org.teiid.common.buffer.STree.insert(STree.java:295)

        at org.teiid.query.processor.relational.EnhancedSortMergeJoinStrategy.createIndex(EnhancedSortMergeJoinStrategy.java:197)

        at org.teiid.query.processor.relational.EnhancedSortMergeJoinStrategy.loadRight(EnhancedSortMergeJoinStrategy.java:308)

        at org.teiid.query.processor.relational.JoinNode.nextBatchDirectInternal(JoinNode.java:257)

        at org.teiid.query.processor.relational.JoinNode.nextBatchDirect(JoinNode.java:195)

        at org.teiid.query.processor.relational.RelationalNode.nextBatch(RelationalNode.java:277)

        at org.teiid.query.processor.BatchCollector$BatchProducerTupleSource.nextTuple(BatchCollector.java:90)

        at org.teiid.query.processor.relational.WindowFunctionProjectNode$1.nextTuple(WindowFunctionProjectNode.java:478)

        at org.teiid.query.processor.relational.WindowFunctionProjectNode.saveInput(WindowFunctionProjectNode.java:500)

        at org.teiid.query.processor.relational.WindowFunctionProjectNode.nextBatchDirect(WindowFunctionProjectNode.java:221)

        at org.teiid.query.processor.relational.RelationalNode.nextBatch(RelationalNode.java:277)

        at org.teiid.query.processor.relational.ProjectNode.nextBatchDirect(ProjectNode.java:146)

        at org.teiid.query.processor.relational.RelationalNode.nextBatch(RelationalNode.java:277)

        at org.teiid.query.processor.relational.UnionAllNode.nextBatchDirectInternal(UnionAllNode.java:165)

        at org.teiid.query.processor.relational.UnionAllNode.nextBatchDirect(UnionAllNode.java:138)

        at org.teiid.query.processor.relational.RelationalNode.nextBatch(RelationalNode.java:277)

        at org.teiid.query.processor.relational.SelectNode.nextBatchDirect(SelectNode.java:100)

        at org.teiid.query.processor.relational.RelationalNode.nextBatch(RelationalNode.java:277)

....

This "space" the process is talking about, is this disk space? Or is it somekind of reserved space (e.g. buffer size) and can it be expanded?

[shawkins]

> So I assume that when a procedure ends and the statement is closed, all related resources like temporary tables etc. are released.

Yes that is the expectation.  Unfortunately I don't think the direct stats from the memory buffer are exposed to monitor consumption.  An issue is needed for that.

> This "space" the process is talking about, is this disk space? Or is it somekind of reserved space (e.g. buffer size) and can it be expanded?

This is the memory buffer space (buffer-service-memory-buffer-space) property.  It defaults to -1 which will auto-size to 40% of the max reserve kb (which can auto-size as well).  What is the max heap size of the vm?  Have there been any adjustments to the default configuration?  How many concurrent operations are running?

You can try manually setting the space property to a relatively large value ~25% of the heap - but it would be good to determine if something is going wrong.

[gadeyne.bram]

I have set -xmX to 4GB but no other adjustments were made to the default configuration.

[shawkins]

With a 4GB and default settings that should result in a 689,165,926 byte memory buffer.  That is serialized byte level storage, not object level on heap, that is used as a serialization buffer to and from disk and as a cache as space permits.  Only concurrent serialization operations should forcibly hold that space - all cache entries should be eligible to eviction causing a disk write when necessary.  So this definitely points to leak.  Can you provide what the client is doing and a sample plan so that I can work towards recreating this?

[gadeyne.bram]

I've send you some source code by email

[shawkins]

An initial issue is [TEIID-5390] Concurrent repeated add attempts create orphaned blocks - JBoss Issue Tracker

I'll start with an initial commit to master.  Can you build from source to test your scenario?

[gadeyne.bram]

I've, created a build from master.

I can not test this again until next week. I'll try for a 1000 patients at once. I suppose I should increase the log level to DEBUG? I see this build is marked as teiid 11. Is the runtime still Wildfly 11 for this?

[shawkins]

> I suppose I should increase the log level to DEBUG?

Yes, that would be good for your test run.

> I see this build is marked as teiid 11. Is the runtime still Wildfly 11 for this?

Yes, it is still at WildFly 11.  We are starting to track closer to Thorntail, which has not yet targeted later WildFly so there wasn't an upgrade yet.

[gadeyne.bram]

Is it oké to just increase the DEBUG level for org.teiid.common.buffer or some other subset of teiid namespace? The log file is increasing with a rate that won't fit my remaining disk space (20 GB) when it get to about 500 admissions...

[shawkins]

Yes it is fine to just do debug on org.teiid.BUFFER_MGR, or you can start with a run without logging and see it works as expected then do the debug log.

[gadeyne.bram]

Hi Steven,

Now it ran oké for 986 patients so I assume that the error was fixed. I had enabled debug logging. Do you want to see the log file?

[shawkins]

Thanks for the update Bram, yes I would like to review it.