Hotfile replication leaves some migration tasks in INITIALIZING state

[ageorget]

Hi,

I enabled few days ago the hotfile replication on our 11.2.4 Rubin instance.
I set up 5 replicas with a 250 threshold to trigger the replication on all pools.

pool.hotfile.replication.enable = true
pool.migration.hotfile.replicas = 5
pool.migration.hotfile.threshold = 250

So it seems to work well (thanks for this!), I can see 5 more replicas created yesterday when the threshold was reached but I also see some migration tasks remaining in INITIALIZING state since then.

"\s pool-lsst* migration ls" | grep -B1 hotfile
pool-lsst-li298a:
    [hotfile-000094B126CB7057472988D2CCD6256F188F] FINISHED     hotfile replication for 000094B126CB7057472988D2CCD6256F188F
pool-lsst-li299a:
    [hotfile-0000EB0C5F929D904B368E3FBF3457076694] FINISHED     hotfile replication for 0000EB0C5F929D904B368E3FBF3457076694
    [hotfile-000094B126CB7057472988D2CCD6256F188F] FINISHED     hotfile replication for 000094B126CB7057472988D2CCD6256F188F
--
pool-lsst-li450a:
    [hotfile-0000EB0C5F929D904B368E3FBF3457076694] FINISHED     hotfile replication for 0000EB0C5F929D904B368E3FBF3457076694
--
pool-lsst-li455a:
    [hotfile-0000EB0C5F929D904B368E3FBF3457076694] FINISHED     hotfile replication for 0000EB0C5F929D904B368E3FBF3457076694
--
pool-lsst-li613a:
    [hotfile-000094B126CB7057472988D2CCD6256F188F] INITIALIZING hotfile replication for 000094B126CB7057472988D2CCD6256F188F
--
pool-lsst-li619a:
    [hotfile-000094B126CB7057472988D2CCD6256F188F] INITIALIZING hotfile replication for 000094B126CB7057472988D2CCD6256F188F
--
pool-lsst-li624a:
    [hotfile-0000EB0C5F929D904B368E3FBF3457076694] FINISHED     hotfile replication for 0000EB0C5F929D904B368E3FBF3457076694
--
pool-lsst-li634a:
    [hotfile-000094B126CB7057472988D2CCD6256F188F] FINISHED     hotfile replication for 000094B126CB7057472988D2CCD6256F188F
pool-lsst-li635a:
    [hotfile-0000EB0C5F929D904B368E3FBF3457076694] FINISHED     hotfile replication for 0000EB0C5F929D904B368E3FBF3457076694
--
pool-lsst-li648a:
    [hotfile-0000EB0C5F929D904B368E3FBF3457076694] FINISHED     hotfile replication for 0000EB0C5F929D904B368E3FBF3457076694

pool-lsst-li613a-Domain) ageorget > migration info hotfile-000094B126CB7057472988D2CCD6256F188F
Command    : hotfile replication for 000094B126CB7057472988D2CCD6256F188F
State      : INITIALIZING
Queued     : 1
Attempts   : 0
Targets    : pool-lsst-li450a,pool-lsst-li296a,pool-lsst-li640a,pool-lsst-li284a,pool-lsst-li609a,pool-lsst-li649a,pool-lsst-li613a,pool-lsst-li625a,pool-lsst-li637a,pool-lsst-li641a,pool-lsst-li653a,pool-lsst-li544a,pool-lsst-li556a,pool-lsst-li451a,pool-lsst-li560a,pool-lsst-li285a,pool-lsst-li297a,pool-lsst-li638a,pool-lsst-li557a,pool-lsst-li448a,pool-lsst-li614a,pool-lsst-li626a,pool-lsst-li630a,pool-lsst-li642a,pool-lsst-li654a,pool-lsst-li545a,pool-lsst-li298a,pool-lsst-li561a,pool-lsst-li286a,pool-lsst-li452a,pool-lsst-li290a,pool-lsst-li627a,pool-lsst-li639a,pool-lsst-li546a,pool-lsst-li558a,pool-lsst-li449a,pool-lsst-li615a,pool-lsst-li631a,pool-lsst-li643a,pool-lsst-li287a,pool-lsst-li299a,pool-lsst-li550a,pool-lsst-li453a,pool-lsst-li562a,pool-lsst-li291a,pool-lsst-li616a,pool-lsst-li628a,pool-lsst-li547a,pool-lsst-li559a,pool-lsst-li454a,pool-lsst-li620a,pool-lsst-li632a,pool-lsst-li644a,pool-lsst-li288a,pool-lsst-li551a,pool-lsst-li563a,pool-lsst-li292a,pool-lsst-li617a,pool-lsst-li629a,pool-lsst-li645a,pool-lsst-li548a,pool-lsst-li455a,pool-lsst-li289a,pool-lsst-li621a,pool-lsst-li633a,pool-lsst-li552a,pool-lsst-li281a,pool-lsst-li293a,pool-lsst-li618a,pool-lsst-li634a,pool-lsst-li646a,pool-lsst-li549a,pool-lsst-li553a,pool-lsst-li610a,pool-lsst-li456a,pool-lsst-li622a,pool-lsst-li650a,pool-lsst-li294a,pool-lsst-li282a,pool-lsst-li623a,pool-lsst-li635a,pool-lsst-li647a,pool-lsst-li554a,pool-lsst-li611a,pool-lsst-li651a,pool-lsst-li283a,pool-lsst-li295a,pool-lsst-li608a,pool-lsst-li612a,pool-lsst-li624a,pool-lsst-li636a,pool-lsst-li648a,pool-lsst-li652a,pool-lsst-li543a,pool-lsst-li555a
Completed  : 0 files; 0 bytes
Total      : 6259186878 bytes
Concurrency: 1
Running tasks:

The first file was on pool-lsst-li619a and replicas on others :

\sn cacheinfoof 000094B126CB7057472988D2CCD6256F188F
 pool-lsst-li298a pool-lsst-li299a pool-lsst-li613a pool-lsst-li619a pool-lsst-li634a pool-lsst-li636a

I found this documentation about hotfile replication in https://github.com/dCache/dcache/blob/master/docs/dev/hotfile-replication.md but I couldn't enable DEBUG level as indicated because the appenders mentioned don't exist :

Runtime Log Level Adjustment
# In the pool's admin shell
log set org.dcache.pool.classic.PoolV4 DEBUG
log set org.dcache.pool.migration.MigrationModule DEBUG

I got :

log set org.dcache.pool.classic.PoolV4 DEBUG
(3) java.lang.IllegalArgumentException: Appender not found from ac_log_set_$_2_3
log set org.dcache.pool.migration.MigrationModule DEBUG
(3) java.lang.IllegalArgumentException: Appender not found from ac_log_set_$_2_3

[DmitryLitvintsev]

I asked Chris to have a loog. As for logger, I believe the correct way to do it:

 log set stdout org.dcache.pool.classic.PoolV4 DEBUG

How big are the pools (in terms of number replicas) where migration jobs are “stuck” in INITIALIZING?

[ageorget]

The pool size is 292TB with 60TB used for now but with 4.5 millions files.
I just tried to start a simple migration job on a pool and it took ~15min to start. Whereas the hotfile migration jobs stayed in INITIALIZING for more than 24 hours.

I enabled the DEBUG mode to check what's happen.

[greenc-FNAL]

@ageorget Have any of the INITIALIZING jobs cleared? I've analyzed the code path for deadlocks, races, etc. and come up blank. When #8144 is completed and merged it will prevent expensive surveys of the repository for hot file migrations, but won't fix anything to do with concurrency safety. If the problems you're encountering aren't due to the slow-down from scanning, then this won't resolve your issue.

[ageorget]

@greenc-FNAL The jobs in INITIALIZING state are FINISHED today, after ~30h in INITIALIZING state.
I cleared the replicas and enabled debug to check it during their next Rubin pipeline run.

[DmitryLitvintsev]

@ageorget OK, this ia good news that they are not stuck. Just likely piled up and eventually FINISH.
But the patch @greenc-FNAL worked on will help too.