Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Possible race condition in GenomicsDBImport multi-interval mode. #5300

Closed
droazen opened this issue Oct 11, 2018 · 8 comments
Closed

Possible race condition in GenomicsDBImport multi-interval mode. #5300

droazen opened this issue Oct 11, 2018 · 8 comments
Assignees
@kgururaj @nalinigans
Labels
bug GenomicsDB
Milestone
Engine-Q42018

Comments

@droazen
Copy link
Contributor

droazen commented Oct 11, 2018

@vdauwera reports getting this error when running GenomicsDBImport with a large interval list as the -L input:

java.util.concurrent.CompletionException: org.broadinstitute.hellbender.exceptions.GATKException: Cannot call query with different interval, expected:1:29867-31003 queried with: 1:68590-70510

Looking at the code that produces this error, this seems like a "should never happen" type of error that would likely only be produced by a race condition of some kind.

Full stderr log follows:

Picked up _JAVA_OPTIONS: -Djava.io.tmpdir=/cromwell_root/tmp.876625c8
04:37:28.801 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/gatk/gatk-package-4.0.9.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
04:37:29.319 INFO  GenomicsDBImport - ------------------------------------------------------------
04:37:29.319 INFO  GenomicsDBImport - The Genome Analysis Toolkit (GATK) v4.0.9.0
04:37:29.320 INFO  GenomicsDBImport - For support and documentation go to https://software.broadinstitute.org/gatk/
04:37:29.320 INFO  GenomicsDBImport - Executing as root@7a7880aef99b on Linux v4.9.0-0.bpo.6-amd64 amd64
04:37:29.321 INFO  GenomicsDBImport - Java runtime: OpenJDK 64-Bit Server VM v1.8.0_171-8u171-b11-0ubuntu0.16.04.1-b11
04:37:29.321 INFO  GenomicsDBImport - Start Date/Time: October 8, 2018 4:37:28 AM UTC
04:37:29.321 INFO  GenomicsDBImport - ------------------------------------------------------------
04:37:29.322 INFO  GenomicsDBImport - ------------------------------------------------------------
04:37:29.322 INFO  GenomicsDBImport - HTSJDK Version: 2.16.1
04:37:29.323 INFO  GenomicsDBImport - Picard Version: 2.18.13
04:37:29.323 INFO  GenomicsDBImport - HTSJDK Defaults.COMPRESSION_LEVEL : 2
04:37:29.323 INFO  GenomicsDBImport - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
04:37:29.324 INFO  GenomicsDBImport - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
04:37:29.324 INFO  GenomicsDBImport - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
04:37:29.324 INFO  GenomicsDBImport - Deflater: IntelDeflater
04:37:29.324 INFO  GenomicsDBImport - Inflater: IntelInflater
04:37:29.325 INFO  GenomicsDBImport - GCS max retries/reopens: 20
04:37:29.325 INFO  GenomicsDBImport - Requester pays: disabled
04:37:29.325 INFO  GenomicsDBImport - Initializing engine
04:37:29.993 INFO  FeatureManager - Using codec BEDCodec to read file file:///cromwell_root/gatk-test-data/intervals/Broad.human.exome.scattered/Broad.human.exome.b37_1_nozero.bed
04:37:30.330 INFO  IntervalArgumentCollection - Processing 18455956 bp from intervals
04:37:30.340 WARN  GenomicsDBImport - A large number of intervals were specified. Using more than 100 intervals in a single import is not recommended and can cause performance to suffer. It is recommended that intervals be aggregated together.
04:37:30.380 INFO  GenomicsDBImport - Done initializing engine
Created workspace /cromwell_root/genomicsdb
04:37:30.677 INFO  GenomicsDBImport - Vid Map JSON file will be written to genomicsdb/vidmap.json
04:37:30.677 INFO  GenomicsDBImport - Callset Map JSON file will be written to genomicsdb/callset.json
04:37:30.677 INFO  GenomicsDBImport - Complete VCF Header will be written to genomicsdb/vcfheader.vcf
04:37:30.678 INFO  GenomicsDBImport - Importing to array - genomicsdb/genomicsdb_array
04:37:30.680 INFO  ProgressMeter - Starting traversal
04:37:30.680 INFO  ProgressMeter -        Current Locus  Elapsed Minutes     Batches Processed   Batches/Minute
04:37:33.253 INFO  GenomicsDBImport - Starting batch input file preload
04:37:35.079 INFO  GenomicsDBImport - Finished batch preload
04:37:35.079 INFO  GenomicsDBImport - Importing batch 1 with 50 samples
04:37:37.079 INFO  GenomicsDBImport - Starting batch input file preload
04:37:38.712 INFO  GenomicsDBImport - Finished batch preload
04:37:38.712 INFO  GenomicsDBImport - Importing batch 1 with 50 samples
04:37:39.162 INFO  GenomicsDBImport - Shutting down engine
[October 8, 2018 4:37:39 AM UTC] org.broadinstitute.hellbender.tools.genomicsdb.GenomicsDBImport done. Elapsed time: 0.17 minutes.
Runtime.totalMemory()=4116185088
java.util.concurrent.CompletionException: org.broadinstitute.hellbender.exceptions.GATKException: Cannot call query with different interval, expected:1:29867-31003 queried with: 1:68590-70510
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273)
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280)
    at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1592)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
Caused by: org.broadinstitute.hellbender.exceptions.GATKException: Cannot call query with different interval, expected:1:29867-31003 queried with: 1:68590-70510
    at org.broadinstitute.hellbender.tools.genomicsdb.GenomicsDBImport$InitializedQueryWrapper.query(GenomicsDBImport.java:769)
    at com.intel.genomicsdb.importer.GenomicsDBImporter.<init>(GenomicsDBImporter.java:165)
    at com.intel.genomicsdb.importer.GenomicsDBImporter.lambda$null$2(GenomicsDBImporter.java:604)
    at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590)
    ... 3 more
04:37:39.167 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.169 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.169 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.169 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.170 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.170 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.171 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.171 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.171 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.171 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.172 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.172 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.172 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.173 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.173 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.173 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.173 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.174 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.174 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.174 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.174 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.175 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.175 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.175 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.176 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.177 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.177 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.178 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.179 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.180 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.180 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.180 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.180 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.181 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.181 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.181 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.181 INFO  GenomicsDBImport - Starting batch input file preload
04:37:39.187 INFO  GenomicsDBImport - Starting batch input file preload
Using GATK jar /gatk/gatk-package-4.0.9.0-local.jar
Running:
    java -Dsamjdk.use_async_io_read_samtools=false -Dsamjdk.use_async_io_write_samtools=true -Dsamjdk.use_async_io_write_tribble=false -Dsamjdk.compression_level=2 -Xmx4g -Xms4g -jar /gatk/gatk-package-4.0.9.0-local.jar GenomicsDBImport --genomicsdb-workspace-path genomicsdb --batch-size 50 -L /cromwell_root/gatk-test-data/intervals/Broad.human.exome.scattered/Broad.human.exome.b37_1_nozero.bed --sample-name-map inputs.list --reader-threads 5 -ip 500
@droazen droazen added this to the Engine-Q42018 milestone Oct 11, 2018
@droazen
Copy link
Contributor Author

droazen commented Oct 11, 2018

@kgururaj @nalinigans Any thoughts on this one?

@nalinigans
Copy link
Collaborator

Will let @kgururaj comment before looking at this code.

@kgururaj
Copy link
Collaborator

kgururaj commented Nov 8, 2018

Would it be possible to provide the interval list used?

@ldgauthier
Copy link
Contributor

ldgauthier commented Nov 9, 2018 •
edited
Loading

I hit this error as well when I was doing a "plumbing" test for the new exome joint calling (I meant to merge the intervals like you suggested, but I made a mistake). That was just one sample over half of chr20. I can email you the inputs.

@ldgauthier
Copy link
Contributor

I can actually replicate this with an interval list with two intervals:

chr1	11719	18516	+	.
chr2	38664	202755	+	.

throws

org.broadinstitute.hellbender.exceptions.GATKException: Cannot call query with different interval, expected:chr1:11719-18516 queried with: chr2:38664-202755
	at org.broadinstitute.hellbender.tools.genomicsdb.GenomicsDBImport$InitializedQueryWrapper.query(GenomicsDBImport.java:816)
	at com.intel.genomicsdb.importer.GenomicsDBImporter.<init>(GenomicsDBImporter.java:136)
	at com.intel.genomicsdb.importer.GenomicsDBImporter.lambda$null$2(GenomicsDBImporter.java:563)
	at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

We typically run with --reader-threads 5 in the pipeline, but if I change it to 1 I can get it to run. That's not a longterm solution, but hopefully it's a good hint and it's a good enough workaround for me for the moment.

@droazen
Copy link
Contributor Author

droazen commented Nov 14, 2018

@kgururaj @nalinigans Just pinging you to make sure you notice @ldgauthier 's comment above where she reproduces this with just 2 intervals.

@droazen
Copy link
Contributor Author

droazen commented Nov 14, 2018

We were looking at this just now, and it seems like the problem might be this line in GenomicsDBImport.getFeatureReadersInParallel():

return new InitializedQueryWrapper(getReaderFromPath(variantPath), intervals.get(0));

Notice that it's unconditionally calling intervals.get(0) in every thread...it looks like this line didn't get updated when multi-interval support was added to the tool, and the multi-interval tests don't run with reader threads > 1.

kgururaj added a commit that referenced this issue Nov 16, 2018
@kgururaj
Fix for #5300 when multiple
8ad1991 
reader-threads are used in the importer. Not a race condition in
GenomicsDB - InitializedQueryWrapper wasn't written for multiple
intervals.

CI test with multiple reader threads
@kgururaj kgururaj mentioned this issue Nov 16, 2018
Merged
@hmkim
Copy link

hmkim commented Nov 17, 2018

I had same issue. @ldgauthier 's comment work well in my case.

kgururaj added a commit that referenced this issue Nov 19, 2018
@kgururaj
Fix for #5300 when multiple
e9f5da7 
reader-threads are used in the importer. Not a race condition in
GenomicsDB - InitializedQueryWrapper wasn't written for multiple
intervals.

CI test with multiple reader threads
droazen pushed a commit that referenced this issue Jan 8, 2019
@kgururaj @droazen
Fix for #5300 when multiple
eb5d4b9 
reader-threads are used in the importer. Not a race condition in
GenomicsDB - InitializedQueryWrapper wasn't written for multiple
intervals.

CI test with multiple reader threads
droazen pushed a commit that referenced this issue Jan 16, 2019
@kgururaj @droazen
GenomicsDB matches CombineGVCFs with input spanning deletions (#5397)
05aa6b2 
* The newest release of GenomicsDB treats spanning deletions (spanning
from earlier positions) as deletions in the min PL value computation.
This behavior now matches the behavior of CombineGVCFs.

A more detailed description of the issue is provided in
#4963

* Deleted a couple of files which are no longer necessary.

* Fixed the index of newMQcalc.combined.g.vcf

* Fix for #5300 when multiple
reader-threads are used in the importer. Not a race condition in
GenomicsDB - InitializedQueryWrapper wasn't written for multiple
intervals.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@kgururaj kgururaj

@nalinigans nalinigans

Labels
bug GenomicsDB
Projects
None yet
Milestone
Engine-Q42018
Development

No branches or pull requests
5 participants
@droazen @hmkim @kgururaj @ldgauthier @nalinigans