[RNNLM] old iteration model cleanup

[slckl]

As outlined in issue #2869, rnnlm training currently retains model files for ALL iterations, which eats storage space very quickly. This PR implements an optional automatic cleanup of rnnlm model files (off by default).

Two cleanup strategies have been implemented: "keep_latest", which retains only a certain number of freshest iterations, and "keep_best", which looks at objf on dev set, and retains only a certain number of iterations with best objf values.

What is implemented:

• cleanup logic in a separate python 3 script, which looks at iterations to clean up based on what the compute_prob log files say about these iterations. Since rnnlm-compute-prob and rnnlm-train processes work in parallel and often one finishes before the other, looking at log files felt like the simplest solution to figure out which iterations are safe to clean up.
• optional invocation of cleanup script from train_rnnlm.sh with extra cleanup arguments added.
• after training is done, there's a get_best_model.py script, which picks out the best model based on dev-set perplexity. This script has been updated to ignore iterations which do have a compute_prob log, but no model files.

What is not done:

• I have not touched any recipes or anything of the sort, so they all should work just like before. However, there's also no demonstration anywhere how to use cleanup functionality.

Sample invocation with cleanup functionality from a training directory looks like this:

rnnlm/train_rnnlm.sh --num-jobs-initial 1 --num-jobs-final 1 \
                    --embedding_l2 $embedding_l2 \
                    --use_gpu_for_diagnostics true \
                    # the new cleanup stuff
                    --cleanup true --cleanup_strategy "keep_latest" \
                    --cleanup_keep_iters 10 \
                    # that's it for cleanup
                    --stage $train_stage --num-epochs $epochs --cmd "$cmd --mem 16G" $dir

For what it's worth, I have verified this works on a private problem, but I haven't tried any of the Kaldi out of the box recipes with this.

[danpovey]

Thanks! @keli78 and @GaofengCheng, I believe you may both be running RNNLM training. Would you mind testing this for me, i.e. running your experiments with these changes? don't forget to let me know once you have done so.

[keli78]

Sure. I'm running a test for this now.

Ke

[GaofengCheng]

Trying today.

[slckl]

Discovered a bug in this, apparently "0.raw" and maybe something else is special, but this treats it as just another iteration and cleans it up. Committing fix in a moment.

Sorry about that.

[slckl]

That's the fix committed. It will now never consider files that belong to iteration 0 for cleanup.

[GaofengCheng]

@slckl
It threw the warnings:

Training neural net (pass 25)
rnnlm/get_best_model.py: warning: no model files found for iteration 1. Skipping.
rnnlm/get_best_model.py: warning: no model files found for iteration 2. Skipping.
rnnlm/get_best_model.py: warning: no model files found for iteration 3. Skipping.
rnnlm/get_best_model.py: warning: no model files found for iteration 4. Skipping.
rnnlm/get_best_model.py: warning: no model files found for iteration 5. Skipping.
rnnlm/get_best_model.py: warning: no model files found for iteration 6. Skipping.
rnnlm/get_best_model.py: warning: no model files found for iteration 7. Skipping.
rnnlm/get_best_model.py: warning: no model files found for iteration 8. Skipping.

[slckl]

Yeah, that's kind of normal. That's the script that originally goes over ALL the iterations and finds the best model. This warning just says that, while there are log files for the given iteration, there are no more model files, presumably because they were cleaned up.

I suppose that really shouldn't be a warning as it's confusing. I'll remove it.

[GaofengCheng]

Thanks for your commit. I'm checking and re-running to test. Because of the warning, the previous code did not generate the final.mdl. It will take another day. Thanks for your work.

[keli78]

Hi @slckl I got many warnings like:
rnnlm/rnnlm_cleanup.py: warning: could not parse objective function from exp/rnnlm_lstm_960cleaned_1a/log/compute_prob.25.log
rnnlm/rnnlm_cleanup.py: warning: could not parse objective function from exp/rnnlm_lstm_960cleaned_1a/log/compute_prob.20.log
......
While these log files look normal.
And after training is done, I got an error:
rnnlm/get_best_model.py: error: could not get best iteration.
I set "cleanup_keep_iters" as 5.

[slckl]

Hi @keli78 could you please copy & paste the contents of any of the compute_prob.XX.log files which caused the warning? The objective parsing should be the same as in get_best_model.py, and it sounds like that also fails.

Fortunately for me, the get_best_model.py code is by @danpovey so maybe it's something else, not my code at fault here, hehe.

But I'd have to see the log file to tell for sure.

[slckl]

Just finished a week long training of a fairly vanilla tdnn-lstm model using cleanup. After all the changes, the final model was picked out just fine.

@keli78 any updates on those logs?
I can fix the log parsing, if that's where the issue is.

[GaofengCheng]

@slckl
I used your latest commit, and it failed as follow:

rnnlm/train_rnnlm.sh: will train for 26 iterations
Training neural net (pass 0)
Training neural net (pass 1)
Training neural net (pass 2)
Training neural net (pass 3)
Training neural net (pass 4)
Training neural net (pass 5)
Training neural net (pass 6)
Training neural net (pass 7)
Training neural net (pass 8)
Training neural net (pass 9)
Training neural net (pass 10)
Training neural net (pass 11)
Training neural net (pass 12)
Training neural net (pass 13)
Training neural net (pass 14)
Training neural net (pass 15)
Training neural net (pass 16)
Training neural net (pass 17)
Training neural net (pass 18)
Training neural net (pass 19)
Training neural net (pass 20)
Training neural net (pass 21)
Training neural net (pass 22)
Training neural net (pass 23)
Training neural net (pass 24)
Training neural net (pass 25)
rnnlm/get_best_model.py: error: could not get best iteration.

I used your scripts/rnnlm to replace my local directory.
Anything I'm wrong?

[slckl]

That should have worked, hmmm. Can you please paste a sample compute_prob.XX.log from this experiment?
I'm particularly interested in lines like:

LOG (rnnlm-compute-prob[5.5.118~1-2489b]:PrintStatsOverall():rnnlm-core-training.cc:118) Overall objf is (-6.574 + -0.0367) = -6.611 over 9.471e+05 words (weighted) in 246 minibatches; exact = (-6.574 + -0.01359) = -6.587

[GaofengCheng]

@slckl FYI

# Running on cs04
# Started at Wed Dec 5 14:11:49 CST 2018
# rnnlm-get-egs --eos-symbol=200006 --bos-symbol=200005 --brk-symbol=200007 --vocab-size=200008 exp/rnnlm_lstm_1a_new_scripts/text/dev.txt ark:- | rnnlm-compute-prob exp/rnnlm_lstm_1a_new_scripts/25.raw "rnnlm-get-word-embedding exp/rnnlm_lstm_1a_new_scripts/word_feats.txt exp/rnnlm_lstm_1a_new_scripts/feat_embedding.25.mat -|" ark:- 
rnnlm-compute-prob exp/rnnlm_lstm_1a_new_scripts/25.raw 'rnnlm-get-word-embedding exp/rnnlm_lstm_1a_new_scripts/word_feats.txt exp/rnnlm_lstm_1a_new_scripts/feat_embedding.25.mat -|' ark:- 
rnnlm-get-egs --eos-symbol=200006 --bos-symbol=200005 --brk-symbol=200007 --vocab-size=200008 exp/rnnlm_lstm_1a_new_scripts/text/dev.txt ark:- 
LOG (rnnlm-compute-prob[5.5]:SelectGpuId():cu-device.cc:128) Manually selected to compute on CPU.
LOG (rnnlm-get-egs[5.5]:Process():rnnlm-example.cc:703) Processed 5624 lines of input.
rnnlm-get-word-embedding exp/rnnlm_lstm_1a_new_scripts/word_feats.txt exp/rnnlm_lstm_1a_new_scripts/feat_embedding.25.mat - 
LOG (rnnlm-compute-prob[5.5]:PrintStatsThisInterval():rnnlm-core-training.cc:100) Objf for minibatches 0 to 9 is (-5.043 + -0.03641) = -5.079 over 3.784e+04 words (weighted); exact = (-5.043 + -0.01707) = -5.06
LOG (rnnlm-compute-prob[5.5]:PrintStatsThisInterval():rnnlm-core-training.cc:100) Objf for minibatches 10 to 19 is (-5.025 + -0.03117) = -5.056 over 3.795e+04 words (weighted); exact = (-5.025 + -0.01265) = -5.037
LOG (rnnlm-compute-prob[5.5]:PrintStatsThisInterval():rnnlm-core-training.cc:100) Objf for minibatches 20 to 29 is (-4.999 + -0.03596) = -5.035 over 3.778e+04 words (weighted); exact = (-4.999 + -0.01689) = -5.016
LOG (rnnlm-compute-prob[5.5]:PrintStatsThisInterval():rnnlm-core-training.cc:100) Objf for minibatches 30 to 39 is (-5.009 + -0.03428) = -5.043 over 3.798e+04 words (weighted); exact = (-5.009 + -0.01588) = -5.025
LOG (rnnlm-compute-prob[5.5]:PrintStatsThisInterval():rnnlm-core-training.cc:100) Objf for minibatches 40 to 49 is (-4.974 + -0.03614) = -5.01 over 3.781e+04 words (weighted); exact = (-4.974 + -0.01762) = -4.991
LOG (rnnlm-get-egs[5.5]:~RnnlmExampleCreator():rnnlm-example.cc:347) Combined 5624/9194 chunks/sequences into 52 minibatches (0 chunks left over)
LOG (rnnlm-get-egs[5.5]:~RnnlmExampleCreator():rnnlm-example.cc:352) Overall there were 22.2195 words per chunk; 176.808 chunks per minibatch.
LOG (rnnlm-compute-prob[5.5]:PrintStatsThisInterval():rnnlm-core-training.cc:100) Objf for minibatches 50 to 51 is (-4.957 + -0.03568) = -4.992 over 4211 words (weighted); exact = (-4.957 + -0.01686) = -4.974
LOG (rnnlm-compute-prob[5.5]:PrintStatsOverall():rnnlm-core-training.cc:118) Overall objf is (-5.009 + -0.03481) = -5.044 over 1.936e+05 words (weighted) in 52 minibatches; exact = (-5.009 + -0.01604) = -5.025
LOG (rnnlm-compute-prob[5.5]:~CachingOptimizingCompiler():nnet-optimize.cc:710) 0.0413 seconds taken in nnet3 compilation total (breakdown: 0.0125 compilation, 0.0214 optimization, 0.000981 shortcut expansion, 0.0042 checking, 0 computing indexes, 0.00228 misc.) + 0 I/O.
-5.04362
# Accounting: time=10038 threads=1
# Finished at Wed Dec 5 16:59:07 CST 2018 with status 0

[slckl]

That looks very much ok.
Are the model files actually present in the training dir? Perhaps cleanup has cleaned up too much, as now get_best_model.py silently skips iterations without model files.

[GaofengCheng]

Your scripts didn't generate the report.txt.
I don't know whether this is a bug?

[slckl]

report.txt is generated after get_best_model.py does its thing. So if get_best_model.py fails, then train_rnnlm.sh never gets to that, so that's unrelated.

Can you confirm that word_embedding.25.mat and 25.raw are actually still present in the training directory?

[GaofengCheng]

No.
Only
feat_embedding.25.mat
and
25.raw

Maybe you confused word_embedding and feat_embedding?

[slckl]

Ah, I changed get_best_model.py to check for word_embedding in model names to verify that iteration has model files present, since it doesn't find anything like that, it skips all iterations. Let me fix that real quick.
I assume that you also have feat_embedding.24.mat, feat_embedding.23.mat etc all the way down to feat_embedding.1.mat?

[GaofengCheng]

Yes, I have.

[slckl]

Yup, so cleanup didn't consider those as well. Sorry about that.

Fixing right now.

[slckl]

There, that should now consider feat_embedding files as well. Could you please retry this with latest changes?

You can just resume training at, say, iteration 24, then cleanup and get_best_model.py should both run, and everything should be ok.

[keli78]

Hi @slckl I tested your newest version and the previous error is gone.

[slckl]

Good to hear, thanks for testing.
I tried running a feature-based LM training yesterday, and the cleanup did work for me there as well now.