vg giraffe runs unusually slowly on Illumina paired-end reads on one user's system

[upsm-123]

Developer, hello!
I used vg giraffe to map resequenced data to a graph pan-genome and obtain a gam file, but this step is progressing extremely slowly. Therefore, I would like to ask if this is normal. Below is a portion of the log file content:
Guessing that ~/mouse.d2.shortread.zipcodes is Short Read Zipcodes
warning[vg::Watchdog]: Thread 6 has been checked in for 10 seconds processing: SRR1174880.372702, SRR1174880.372702
warning[vg::Watchdog]: Thread 7 has been checked in for 10 seconds processing: SRR1174880.622813, SRR1174880.622813
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: SRR1174880.646249, SRR1174880.646249
warning[vg::Watchdog]: Thread 7 finally checked out after 21 seconds and 22972 kb memory growth processing: SRR1174880.622813, SRR1174880.622813
warning[vg::Watchdog]: Thread 10 has been checked in for 10 seconds processing: SRR1174880.1150056, SRR1174880.1150056
warning[vg::Watchdog]: Thread 10 finally checked out after 16 seconds and 20596 kb memory growth processing: SRR1174880.1150056, SRR1174880.1150056
warning[vg::Watchdog]: Thread 7 has been checked in for 10 seconds processing: SRR1174880.1335411, SRR1174880.1335411
warning[vg::Watchdog]: Thread 0 has been checked in for 10 seconds processing: SRR1174880.1771197, SRR1174880.1771197
warning[vg::Watchdog]: Thread 4 has been checked in for 10 seconds processing: SRR1174880.1575454, SRR1174880.1575454
warning[vg::Watchdog]: Thread 4 finally checked out after 13 seconds and 0 kb memory growth processing: SRR1174880.1575454, SRR1174880.1575454
warning[vg::Watchdog]: Thread 0 finally checked out after 71 seconds and 0 kb memory growth processing: SRR1174880.1771197, SRR1174880.1771197
warning[vg::Watchdog]: Thread 5 has been checked in for 10 seconds processing: SRR1174880.2794036, SRR1174880.2794036
warning[vg::Watchdog]: Thread 2 has been checked in for 10 seconds processing: SRR1174880.2842518, SRR1174880.2842518
warning[vg::Watchdog]: Thread 1 has been checked in for 10 seconds processing: SRR1174880.2902241, SRR1174880.2902241
warning[vg::Watchdog]: Thread 2 finally checked out after 29 seconds and 4352 kb memory growth processing: SRR1174880.2842518, SRR1174880.2842518
warning[vg::Watchdog]: Thread 1 finally checked out after 32 seconds and 4352 kb memory growth processing: SRR1174880.2902241, SRR1174880.2902241
warning[vg::Watchdog]: Thread 0 has been checked in for 10 seconds processing: SRR1174880.3707850, SRR1174880.3707850
warning[vg::Watchdog]: Thread 11 has been checked in for 10 seconds processing: SRR1174880.3405077, SRR1174880.3405077
warning[vg::Watchdog]: Thread 7 finally checked out after 682 seconds and 203244 kb memory growth processing: SRR1174880.1335411, SRR1174880.1335411
warning[vg::Watchdog]: Thread 5 finally checked out after 1046 seconds and 4352 kb memory growth processing: SRR1174880.2794036, SRR1174880.2794036
warning[vg::Watchdog]: Thread 3 finally checked out after 25102 seconds and 246812 kb memory growth processing: SRR1174880.646249, SRR1174880.646249
warning[vg::Watchdog]: Thread 0 finally checked out after 40747 seconds and 0 kb memory growth processing: SRR1174880.3707850, SRR1174880.3707850
warning[vg::Watchdog]: Thread 10 has been checked in for 10 seconds processing: SRR1174880.3718121, SRR1174880.3718121
warning[vg::Watchdog]: Thread 7 has been checked in for 10 seconds processing: SRR1174880.3832901, SRR1174880.3832901
warning[vg::Watchdog]: Thread 8 has been checked in for 10 seconds processing: SRR1174880.4005631, SRR1174880.4005631
warning[vg::Watchdog]: Thread 2 has been checked in for 10 seconds processing: SRR1174880.4308446, SRR1174880.4308446
warning[vg::Watchdog]: Thread 5 has been checked in for 10 seconds processing: SRR1174880.4336439, SRR1174880.4336439
warning[vg::Watchdog]: Thread 8 finally checked out after 54 seconds and 0 kb memory growth processing: SRR1174880.4005631, SRR1174880.4005631
warning[vg::Watchdog]: Thread 8 has been checked in for 10 seconds processing: SRR1174880.4704492, SRR1174880.4704492
warning[vg::Watchdog]: Thread 9 has been checked in for 10 seconds processing: SRR1174880.4712685, SRR1174880.4712685
warning[vg::Watchdog]: Thread 8 finally checked out after 32 seconds and 0 kb memory growth processing: SRR1174880.4704492, SRR1174880.4704492
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: SRR1174880.4946622, SRR1174880.4946622

[upsm-123]

Sometimes，we can see：
warning[vg::giraffe]: Refusing to perform too-large rescue alignment of 125 bp against 13062 bp ordered subgraph for read HWI-D00591:121:C6T49ANXX:1:1101:2716:26626 which would use more than 1572864 cells and might exhaust Dozeu's allocator; suppressing further warnings.

[jltsiren]

It's difficult to say anything without further information. What kind of data you have in the graph, how did you build it, and what are you trying to align to it? What kind of system are you using?

Have you looked at Giraffe best practices?

One common issue is that the graph is not a useful alignment of the underlying haplotypes. Giraffe prefers graphs that have a linear high-level structure and avoid complex regions, high-degree nodes, long-distance edges, and sequence duplication.

Some distributed/network file systems don't handle memory-mapped files well. Giraffe is sometimes slow if the distance index is on such a file system, especially if multiple jobs are using the same index. In such cases, it may help if you make the distance index file read-only or copy it to a local disk for each job.

[upsm-123]

Hi. I added "-p" option and launched again the job.
nohup: ignoring input
开始处理样本: CRR041289
Preparing Indexes
Loading Minimizer Index
Loading Zipcodes
Loading GBZ
Loading Distance Index v2
Paging in Distance Index v2
Initializing MinimizerMapper
Loading and initialization: 125.512 seconds
Of which Distance Index v2 paging: 0.202229 seconds
Mapping reads to "-" (GAM)
--watchdog-timeout 10
--batch-size 512
--match 1
--mismatch 4
--gap-open 6
--gap-extend 1
--full-l-bonus 5
--max-multimaps 1
--hit-cap 10
--hard-hit-cap 500
--score-fraction 0.9
--max-min 500
--min-coverage-flank 250
--num-bp-per-min 1000
--downsample-window-length 18446744073709551615
--downsample-window-count 0
--distance-limit 200
--max-extensions 800
--max-alignments 8
--cluster-score 50
--pad-cluster-score 20
--cluster-coverage 0.3
--max-extension-mismatches 4
--extension-score 1
--extension-set 20
--rescue-attempts 15
--max-fragment-length 2000
--paired-distance-limit 2
--rescue-subgraph-size 4
--rescue-seed-limit 100
--mapq-score-window 0
--mapq-score-scale 1
--zipcode-tree-score-threshold 50
--pad-zipcode-tree-score-threshold 20
--zipcode-tree-coverage-threshold 0.3
--zipcode-tree-scale 2
--min-to-fragment 4
--max-to-fragment 10
--max-direct-chain 0
--gapless-extension-limit 0
--fragment-max-graph-lookback-bases 300
--fragment-max-graph-lookback-bases-per-base 0.03
--fragment-max-read-lookback-bases 18446744073709551615
--fragment-max-read-lookback-bases-per-base 1
--max-fragments 18446744073709551615
--fragment-max-indel-bases 2000
--fragment-max-indel-bases-per-base 0.2
--fragment-gap-scale 1
--fragment-points-per-possible-match 0
--fragment-score-fraction 0.1
--fragment-max-min-score 1.79769e+308
--fragment-min-score 60
--fragment-set-score-threshold 0
--min-chaining-problems 1
--max-chaining-problems 2147483647
--max-graph-lookback-bases 3000
--max-graph-lookback-bases-per-base 0.3
--max-read-lookback-bases 18446744073709551615
--max-read-lookback-bases-per-base 1
--max-indel-bases 2000
--max-indel-bases-per-base 0.2
--item-bonus 0
--item-scale 1
--gap-scale 1
--points-per-possible-match 0
--chain-score-threshold 100
--min-chains 4
--min-chain-score-per-base 0.01
--max-min-chain-score 200
--max-skipped-bases 0
--max-chains-per-tree 1
--max-chain-connection 100
--max-tail-length 100
--max-dp-cells 18446744073709551615
--max-tail-gap 18446744073709551615
--max-middle-gap 18446744073709551615
--max-tail-dp-length 30000
--max-middle-dp-length 2147483647
--wfa-max-mismatches 2
--wfa-max-mismatches-per-base 0.1
--wfa-max-max-mismatches 20
--wfa-distance 10
--wfa-distance-per-base 0.1
--wfa-max-distance 200
--min-unique-node-fraction 0
--rescue-algorithm dozeu
Not counting CPU instructions because perf events are unavailable: Permission denied
Using fragment length estimate: 460.314 +/- 55.4348
warning[vg::Watchdog]: Thread 5 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1101:4875:6797, HISEQ:124:C6U8FANXX:5:1101:4875:6797
warning[vg::Watchdog]: Thread 2 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1101:9106:10263, HISEQ:124:C6U8FANXX:5:1101:9106:10263
warning[vg::Watchdog]: Thread 5 finally checked out after 12 seconds and 561036 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1101:4875:6797, HISEQ:124:C6U8FANXX:5:1101:4875:6797
warning[vg::Watchdog]: Thread 10 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1101:1789:22273, HISEQ:124:C6U8FANXX:5:1101:1789:22273
warning[vg::Watchdog]: Thread 2 finally checked out after 15 seconds and 53132 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1101:9106:10263, HISEQ:124:C6U8FANXX:5:1101:9106:10263
warning[vg::Watchdog]: Thread 0 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1101:13851:89436, HISEQ:124:C6U8FANXX:5:1101:13851:89436
warning[vg::Watchdog]: Thread 11 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1101:17322:30668, HISEQ:124:C6U8FANXX:5:1101:17322:30668
warning[vg::Watchdog]: Thread 0 finally checked out after 14 seconds and 2048 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1101:13851:89436, HISEQ:124:C6U8FANXX:5:1101:13851:89436
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1101:19972:48886, HISEQ:124:C6U8FANXX:5:1101:19972:48886
warning[vg::Watchdog]: Thread 3 finally checked out after 19 seconds and 270508 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1101:19972:48886, HISEQ:124:C6U8FANXX:5:1101:19972:48886
warning[vg::Watchdog]: Thread 6 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1102:14649:8009, HISEQ:124:C6U8FANXX:5:1102:14649:8009
warning[vg::Watchdog]: Thread 7 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1102:15858:12418, HISEQ:124:C6U8FANXX:5:1102:15858:12418
warning[vg::Watchdog]: Thread 9 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1102:10544:79584, HISEQ:124:C6U8FANXX:5:1102:10544:79584
warning[vg::Watchdog]: Thread 8 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1102:2127:83730, HISEQ:124:C6U8FANXX:5:1102:2127:83730
warning[vg::Watchdog]: Thread 1 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1103:18928:8926, HISEQ:124:C6U8FANXX:5:1103:18928:8926
warning[vg::Watchdog]: Thread 8 finally checked out after 38 seconds and 15792 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1102:2127:83730, HISEQ:124:C6U8FANXX:5:1102:2127:83730
warning[vg::Watchdog]: Thread 4 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1103:19337:55394, HISEQ:124:C6U8FANXX:5:1103:19337:55394
warning[vg::Watchdog]: Thread 0 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1104:3575:72010, HISEQ:124:C6U8FANXX:5:1104:3575:72010
warning[vg::Watchdog]: Thread 2 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1103:18566:89848, HISEQ:124:C6U8FANXX:5:1103:18566:89848
warning[vg::Watchdog]: Thread 5 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1104:10118:10384, HISEQ:124:C6U8FANXX:5:1104:10118:10384
warning[vg::Watchdog]: Thread 5 finally checked out after 14 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1104:10118:10384, HISEQ:124:C6U8FANXX:5:1104:10118:10384
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1104:17799:17765, HISEQ:124:C6U8FANXX:5:1104:17799:17765
warning[vg::Watchdog]: Thread 2 finally checked out after 46 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1103:18566:89848, HISEQ:124:C6U8FANXX:5:1103:18566:89848
warning[vg::Watchdog]: Thread 6 finally checked out after 143 seconds and 30720 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1102:14649:8009, HISEQ:124:C6U8FANXX:5:1102:14649:8009
warning[vg::Watchdog]: Thread 8 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1104:2834:26634, HISEQ:124:C6U8FANXX:5:1104:2834:26634
warning[vg::Watchdog]: Thread 5 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1104:12416:36398, HISEQ:124:C6U8FANXX:5:1104:12416:36398
warning[vg::Watchdog]: Thread 3 finally checked out after 41 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1104:17799:17765, HISEQ:124:C6U8FANXX:5:1104:17799:17765
warning[vg::Watchdog]: Thread 4 finally checked out after 107 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1103:19337:55394, HISEQ:124:C6U8FANXX:5:1103:19337:55394
warning[vg::Watchdog]: Thread 8 finally checked out after 198 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1104:2834:26634, HISEQ:124:C6U8FANXX:5:1104:2834:26634
warning[vg::Watchdog]: Thread 0 finally checked out after 266 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1104:3575:72010, HISEQ:124:C6U8FANXX:5:1104:3575:72010
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1105:5834:5894, HISEQ:124:C6U8FANXX:5:1105:5834:5894
warning[vg::Watchdog]: Thread 8 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1105:13377:18875, HISEQ:124:C6U8FANXX:5:1105:13377:18875
warning[vg::Watchdog]: Thread 3 finally checked out after 31 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1105:5834:5894, HISEQ:124:C6U8FANXX:5:1105:5834:5894
warning[vg::Watchdog]: Thread 6 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1105:20835:51617, HISEQ:124:C6U8FANXX:5:1105:20835:51617
warning[vg::Watchdog]: Thread 7 finally checked out after 405 seconds and 28672 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1102:15858:12418, HISEQ:124:C6U8FANXX:5:1102:15858:12418
warning[vg::Watchdog]: Thread 8 finally checked out after 43 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1105:13377:18875, HISEQ:124:C6U8FANXX:5:1105:13377:18875
warning[vg::Watchdog]: Thread 7 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1106:2455:9376, HISEQ:124:C6U8FANXX:5:1106:2455:9376
warning[vg::Watchdog]: Thread 7 finally checked out after 17 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1106:2455:9376, HISEQ:124:C6U8FANXX:5:1106:2455:9376
warning[vg::Watchdog]: Thread 0 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1107:4947:74146, HISEQ:124:C6U8FANXX:5:1107:4947:74146
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1106:5989:66520, HISEQ:124:C6U8FANXX:5:1106:5989:66520
warning[vg::Watchdog]: Thread 3 finally checked out after 18 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1106:5989:66520, HISEQ:124:C6U8FANXX:5:1106:5989:66520
warning[vg::Watchdog]: Thread 8 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1107:12423:5598, HISEQ:124:C6U8FANXX:5:1107:12423:5598
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1107:7942:40596, HISEQ:124:C6U8FANXX:5:1107:7942:40596
warning[vg::Watchdog]: Thread 2 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1107:12146:51406, HISEQ:124:C6U8FANXX:5:1107:12146:51406
warning[vg::Watchdog]: Thread 7 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1107:9367:62351, HISEQ:124:C6U8FANXX:5:1107:9367:62351
warning[vg::Watchdog]: Thread 7 finally checked out after 35 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1107:9367:62351, HISEQ:124:C6U8FANXX:5:1107:9367:62351
warning[vg::Watchdog]: Thread 1 finally checked out after 630 seconds and 13744 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1103:18928:8926, HISEQ:124:C6U8FANXX:5:1103:18928:8926
warning[vg::Watchdog]: Thread 8 finally checked out after 282 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1107:12423:5598, HISEQ:124:C6U8FANXX:5:1107:12423:5598
warning[vg::Watchdog]: Thread 2 finally checked out after 354 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1107:12146:51406, HISEQ:124:C6U8FANXX:5:1107:12146:51406
warning[vg::Watchdog]: Thread 0 finally checked out after 629 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1107:4947:74146, HISEQ:124:C6U8FANXX:5:1107:4947:74146
warning[vg::Watchdog]: Thread 2 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1107:6524:83125, HISEQ:124:C6U8FANXX:5:1107:6524:83125
warning[vg::Watchdog]: Thread 4 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1108:11172:6667, HISEQ:124:C6U8FANXX:5:1108:11172:6667
warning[vg::Watchdog]: Thread 0 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1109:1349:36047, HISEQ:124:C6U8FANXX:5:1109:1349:36047
warning[vg::Watchdog]: Thread 1 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1108:15792:33501, HISEQ:124:C6U8FANXX:5:1108:15792:33501
warning[vg::Watchdog]: Thread 0 finally checked out after 18 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1109:1349:36047, HISEQ:124:C6U8FANXX:5:1109:1349:36047
warning[vg::Watchdog]: Thread 7 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1108:2422:51043, HISEQ:124:C6U8FANXX:5:1108:2422:51043
warning[vg::Watchdog]: Thread 3 finally checked out after 678 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1107:7942:40596, HISEQ:124:C6U8FANXX:5:1107:7942:40596
warning[vg::Watchdog]: Thread 8 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1108:10534:75439, HISEQ:124:C6U8FANXX:5:1108:10534:75439
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1108:4761:82363, HISEQ:124:C6U8FANXX:5:1108:4761:82363
warning[vg::Watchdog]: Thread 3 finally checked out after 20 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1108:4761:82363, HISEQ:124:C6U8FANXX:5:1108:4761:82363
warning[vg::Watchdog]: Thread 0 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1110:6845:44636, HISEQ:124:C6U8FANXX:5:1110:6845:44636
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1109:18875:22264, HISEQ:124:C6U8FANXX:5:1109:18875:22264
warning[vg::Watchdog]: Thread 3 finally checked out after 13 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1109:18875:22264, HISEQ:124:C6U8FANXX:5:1109:18875:22264
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1109:8102:41645, HISEQ:124:C6U8FANXX:5:1109:8102:41645
warning[vg::Watchdog]: Thread 8 finally checked out after 265 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1108:10534:75439, HISEQ:124:C6U8FANXX:5:1108:10534:75439
warning[vg::Watchdog]: Thread 1 finally checked out after 346 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1108:15792:33501, HISEQ:124:C6U8FANXX:5:1108:15792:33501
warning[vg::Watchdog]: Thread 8 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1109:8687:42369, HISEQ:124:C6U8FANXX:5:1109:8687:42369
warning[vg::Watchdog]: Thread 8 finally checked out after 30 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1109:8687:42369, HISEQ:124:C6U8FANXX:5:1109:8687:42369
warning[vg::Watchdog]: Thread 8 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1109:7462:67294, HISEQ:124:C6U8FANXX:5:1109:7462:67294
warning[vg::Watchdog]: Thread 1 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1110:13789:20012, HISEQ:124:C6U8FANXX:5:1110:13789:20012
warning[vg::Watchdog]: Thread 1 finally checked out after 72 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1110:13789:20012, HISEQ:124:C6U8FANXX:5:1110:13789:20012
warning[vg::Watchdog]: Thread 3 finally checked out after 280 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1109:8102:41645, HISEQ:124:C6U8FANXX:5:1109:8102:41645
warning[vg::Watchdog]: Thread 3 has been checked in for 10 seconds processing: HISEQ:124:C6U8FANXX:5:1110:13939:38091, HISEQ:124:C6U8FANXX:5:1110:13939:38091
warning[vg::Watchdog]: Thread 3 finally checked out after 28 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1110:13939:38091, HISEQ:124:C6U8FANXX:5:1110:13939:38091
warning[vg::Watchdog]: Thread 6 finally checked out after 1402 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1105:20835:51617, HISEQ:124:C6U8FANXX:5:1105:20835:51617
warning[vg::Watchdog]: Thread 2 finally checked out after 711 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1107:6524:83125, HISEQ:124:C6U8FANXX:5:1107:6524:83125
warning[vg::Watchdog]: Thread 4 finally checked out after 1556 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1108:11172:6667, HISEQ:124:C6U8FANXX:5:1108:11172:6667
warning[vg::Watchdog]: Thread 7 finally checked out after 3337 seconds and 0 kb memory growth processing: HISEQ:124:C6U8FANXX:5:1108:2422:51043, HISEQ:124:C6U8FANXX:5:1108:2422:51043

如果没有进一步的信息，很难说什么。图表中有什么样的数据，你是如何构建的，你试图与它保持一致？您使用什么样的系统？

你看过长颈鹿的最佳实践吗？

一个常见的问题是该图不是底层单倍型的有用对齐方式。长颈鹿更喜欢具有线性高级结构的图，避免复杂区域、高次节点、长距离边和序列重复。

某些分布式/网络文件系统不能很好地处理内存映射文件。如果距离索引位于此类文件系统上，则 Giraffe 有时会很慢，尤其是当多个作业使用相同的索引时。在这种情况下，将距离索引文件设为只读或将其复制到每个作业的本地磁盘可能会有所帮助。

[upsm-123]

The output file size is not growing at a steady rate. I set -t 12, but after running for a while, the CPU usage suddenly dropped from 1200 to around 700.

[adamnovak]

That behavior of dropping to 700% CPU usage is consistent with the problem being that a few reads are very slow to map.

Look at this message from the first log:

warning[vg::Watchdog]: Thread 3 finally checked out after 25102 seconds and 246812 kb memory growth processing: SRR1174880.646249, SRR1174880.646249

That's way more time than a read pair ought to take. This is probably one of the very slow reads that are causing the problem.

Can you please share the graph you are using, and the sequences for that read pair, so we can try and reproduce the problem?

As a workaround, you could try chmod -w your_graph.dist, or to move the .dist file to /tmp or another local storage location and pass it on the command line like vg giraffe --dist-name /tmp/your_graph.dist. If your problem is actually coming from a slow network filesystem for the distance index, which then makes all the reads much slower and thus makes what would have been merely somewhat slow reads into pathologically slow reads, then that would solve it. Please let us know if it does.

But I suspect the real problem is with the shape of the graph; if the graph is too tangled in some places, reads that touch those places might take too long to map. We can't diagnose such an issue for you any more specifically without access to the graph or a description of how you got it. Did you build this graph with Minigraph-Cactus, PGGB, or some other tool? Or did you download it from somewhere?

[upsm-123]

The MC I used is a graph pan-genome constructed from 25 genomes.
I ran chmod -w my_graph.dist, but the issue persists. The sequences for alignment were downloaded from the internet as second-generation sequencing data.

这种下降到 700% CPU 使用率的行为与一些读取映射速度非常慢的问题一致。

查看第一个日志中的此消息：

warning[vg::Watchdog]: Thread 3 finally checked out after 25102 seconds and 246812 kb memory growth processing: SRR1174880.646249, SRR1174880.646249

这比阅读对应该花费的时间要多得多。这可能是导致问题的非常慢的读取之一。

您能否分享您正在使用的图形以及该读取对的序列，以便我们可以尝试重现问题？

作为解决方法，您可以尝试 或将文件移动到或其他本地存储位置，并在命令行上传递它，例如 。如果你的问题实际上来自距离索引的慢速网络文件系统，这会使所有读取速度变慢得多，从而使原本只是有点慢的读取变成病态的缓慢读取，那么这将解决它。如果有，请告诉我们。chmod -w your_graph.dist``.dist``/tmp``vg giraffe --dist-name /tmp/your_graph.dist

但我怀疑真正的问题在于图表的形状;如果图形在某些地方过于纠结，则接触这些地方的读取可能需要很长时间才能映射。如果无法访问图表或描述您是如何获得该问题的，我们就无法更具体地为您诊断此类问题。你是用 Minigraph-Cactus、PGGB 还是其他工具构建这个图表的？还是你从某个地方下载的？

[upsm-123]

Could it be an issue with the sequencing samples? I tested several samples and found that some ran very quickly with stable output, while others did not perform well. However, all these samples were sequenced on the same platform.

[upsm-123]

"if the graph is too tangled in some places, reads that touch those places might take too long to map." If that's really the case, is there anything we can do about it?

[adamnovak]

Minigraph-Cactus graphs should be the right shape overall, unless something has gone wrong with their construction.

Is there anything interesting about the quality score or read length distributions between the samples that work well and the samples that don't? Or the genetic distance between them and the assemblies in the graph?

If you want to troubleshoot the graph construction, I think @glennhickey is the right person for support on the Minigraph-Cactus pipeline.

If you could provide some of the very slow reads, and the graph itself, or at least the graph and some linear assembly positions you think some of those very slow reads ought to be near, then we could look and see if it looks like there's something to be fixed in Minigraph-Cactus.

You could also try fiddling with the Giraffe parameters to try and make it lazier, so it does less work and maybe can then map your reads. You could start by trying --parameter-preset fast, and if that's not enough you can start reducing --hard-hit-cap, --max-extensions, and/or --max-alignments. But that's likely to make the mappings less accurate.

[leone93]

@adamnovak @upsm-123 I find the same problem.
I tried the last three versions of VG (from 1.66 to 1.68) to be sure it's not related to this, but I see the same pattern.
I'm aligning to the cactus clipped pangenome, and it doesn't seem related to the pangenome but rather to some of the Illumina reads used.
I tried every preset fast, lower --hard-hit-cap, --max-extension etc, different index etc. but nothing worked.

Then I just noticed that the program starts okay at the beginning but then starts to have this problem. This made me think about the fact that the program estimates the pair reads length with the first 1000 reads. And this was shorter than the expected average of the library.
So I just corrected adding the parameters for considering reads length of my library with a big stdev and everything worked fine: --fragment-mean 500 --fragment-stdev 100 (leaving other default parameters and preset fast)

I think the problem is that giraffe start to struggle when find pair of reads with the distance bigger than what he estimate.
If you need anything to do a better debugging @adamnovak let me know.

[zhangyehao]

@leone93 I’m encountering the same issue. I’ve adjusted the --fragment-mean and --fragment-stdev parameters based on the first 50,000 reads, but the problem still remains. Could you suggest a better approach?

[leone93]

Dear @zhangyehao, fortunately, in my case, simply increasing those two parameters enables giraffe to work with paired ends. What is the estimated size of your library?

[zhangyehao]

@leone93 My --fragment-mean and --fragment-stdev parameters are determined based on the first 50,000 paired reads. Some samples work fine, but there are still some that don’t. For example, for one sample with “Using fragment length estimate: 781.7 +/- 47.2”, the following messages appear:
warning[vg::Watchdog]: Thread 2 has been checked in for 10 seconds processing: SRR836315.811522, SRR836315.811522
warning[vg::Watchdog]: Thread 2 finally checked out after 3959 seconds and 303096 kb memory growth processing: SRR836315.811522, SRR836315.811522
......................

[leone93]

Did you see if the problem comes after the first 50k reads? Just a silly question
You could even try less conservative parameter like --parameter-preset fast --fragment-mean 800 --fragment-stdev 100. Let me know