get a new log for rnnlm_h300

1 files changed, 7988 insertions, 8201 deletions

diff --git a/nerv/examples/lmptb/logs/LOG-tnn-h300 b/nerv/examples/lmptb/logs/LOG-tnn-h300
index 77fd612..3e99c5d 100644
--- a/nerv/examples/lmptb/logs/LOG-tnn-h300
+++ b/nerv/examples/lmptb/logs/LOG-tnn-h300
@@ -1,69 +1,64 @@
 Greetings
-[SCHEDULER]: applying arg[2](global_conf.hidden_size=300)...
+[SCHEDULER]: not user setting, all default...
 [SCHEDULER]: printing global_conf...
+log_fn	/home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnnh300ch15ba10slr1wc1e-06/log_lstm_tnn_train-test_TT12_23_15-25-01
 test_fn	/home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/ptb.test.txt.adds
 train_fn	/home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/ptb.train.txt.adds
-param_random	function: 0x40237598
-train_fn_shuf_bak	/home/slhome/txh18/workspace/nerv/play/dagL_test/train_fn_shuf_bak
-decay_iter	16
-mmat_type	table: 0x409280f8
+param_random	function: 0x41a72790
+train_fn_shuf_bak	/home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnnh300ch15ba10slr1wc1e-06/train_fn_shuf_bak
+decay_iter	15
+mmat_type	table: 0x4148c690
 vocab_fn	/home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/vocab
-train_fn_shuf	/home/slhome/txh18/workspace/nerv/play/dagL_test/train_fn_shuf
-param_fn	/home/slhome/txh18/workspace/nerv/play/dagL_test/params
+train_fn_shuf	/home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnnh300ch15ba10slr1wc1e-06/train_fn_shuf
+work_dir_base	/home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnn
+param_fn	/home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnnh300ch15ba10slr1wc1e-06/params
 log_w_num	40000
-work_dir	/home/slhome/txh18/workspace/nerv/play/dagL_test
+work_dir	/home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnnh300ch15ba10slr1wc1e-06
 batch_size	10
 hidden_size	300
 timer	nerv.Timer
 sche_log_pre	[SCHEDULER]:
 nn_act_default	0
-max_iter	35
+max_iter	30
 valid_fn	/home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/ptb.valid.txt.adds
 lrate	1
 momentum	0
-wcost	1e-05
+wcost	1e-06
 chunk_size	15
-cumat_type	table: 0x40935010
+cumat_type	table: 0x4149e6a8
 [SCHEDULER]: printing training scheduling options...
 lr_half	false
 start_iter	-1
+test_iter	-1
 ppl_last	100000
 [SCHEDULER]: printing training scheduling end.
 [SCHEDULER]: creating work_dir...
+(15:25:07 2015-12-23)[nerv] info: CAUTION[LOG_REDIRECT], all nerv.printf/info/warning/error calls will be double-written to /home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnnh300ch15ba10slr1wc1e-06/log_lstm_tnn_train-test_TT12_23_15-25-01
 [SCHEDULER]: building vocab...
 [LOG]LMVocab: Vocab building on file /home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/vocab...
 [LOG]LMVocab: Building finished, vocab size now is 10000.
 [SCHEDULER]: preparing parameters...
-[SCHEDULER]: first time, generating parameters...
+[SCHEDULER]: first time, prepare some pre-set parameters, and leaving other parameters to auto-generation...
 ===INITIAL VALIDATION===
 [SCHEDULER]: preparing parameters...
-[SCHEDULER]: loading parameter from file /home/slhome/txh18/workspace/nerv/play/dagL_test/params.0...
+[SCHEDULER]: loading parameter from file /home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnnh300ch15ba10slr1wc1e-06/params.0...
 reading chunk 0 from 0
-metadata: return {type="nerv.LinearTransParam",id="ltp_ih"}
-
-reading chunk 1 from 34510155
-metadata: return {type="nerv.LinearTransParam",id="ltp_hh"}
-
-reading chunk 2 from 35545278
-metadata: return {type="nerv.LinearTransParam",id="ltp_ho"}
-
-reading chunk 3 from 70045626
-metadata: return {type="nerv.BiasParam",id="bp_h"}
-
-reading chunk 4 from 70049129
-metadata: return {type="nerv.BiasParam",id="bp_o"}
-
-reading chunk 5 from 70164107
 [SCHEDULER]: preparing parameters end.
 [SCHEDULER]: preparing layers...
-(10:08:46 2015-11-18)[nerv] info: create layer: recurrentL1
-(10:08:46 2015-11-18)[nerv] info: create layer: sigmoidL1
-(10:08:46 2015-11-18)[nerv] info: create layer: combinerL1
-(10:08:46 2015-11-18)[nerv] info: create layer: outputL
-(10:08:46 2015-11-18)[nerv] info: create layer: softmaxL
-(10:08:46 2015-11-18)[nerv] info: create layer: selectL1
+(15:25:10 2015-12-23)[nerv] info: create layer: sigmoidL1
+(15:25:10 2015-12-23)[nerv] info: create layer: combinerL1
+(15:25:10 2015-12-23)[nerv] info: create layer: selectL1
+(15:25:10 2015-12-23)[nerv] info: Param [ltp] of layer [selectL1] is not found in layer_conf or layer_conf.paramRepo, switch to auto-generate.
+(15:25:22 2015-12-23)[nerv] info: create layer: outputL
+(15:25:22 2015-12-23)[nerv] info: Param [ltp] of layer [outputL] is not found in layer_conf or layer_conf.paramRepo, switch to auto-generate.
+(15:25:35 2015-12-23)[nerv] info: Param [bp] of layer [outputL] is not found in layer_conf or layer_conf.paramRepo, switch to auto-generate.
+(15:25:35 2015-12-23)[nerv] info: create layer: softmaxL
+(15:25:35 2015-12-23)[nerv] info: create layer: recurrentL1
+(15:25:35 2015-12-23)[nerv] info: Param [bp] of layer [recurrentL1] is not found in layer_conf or layer_conf.paramRepo, switch to auto-generate.
+(15:25:35 2015-12-23)[nerv] info: Param [ltp_hh] of layer [recurrentL1] is not found in layer_conf or layer_conf.paramRepo, switch to auto-generate.
 [SCHEDULER]: preparing layers end.
 [SCHEDULER]: Generate and initing TNN ...
+(15:25:35 2015-12-23)[nerv] info: tnn(TNN) will extend storage beyond MB border for time steps 5...
 <input>	selectL1	0
 selectL1	recurrentL1	0
 recurrentL1	sigmoidL1	0
@@ -79,54 +74,70 @@ combinerL1	#dim_in:	1	#dim_out:	2	#i_conns_p:	1	#o_conns_p	2
 sigmoidL1	#dim_in:	1	#dim_out:	1	#i_conns_p:	1	#o_conns_p	1
 selectL1	#dim_in:	1	#dim_out:	1	#i_conns_p:	0	#o_conns_p	1
 softmaxL	#dim_in:	2	#dim_out:	1	#i_conns_p:	1	#o_conns_p	0
-TNN initing storage	selectL1	->	recurrentL1
-TNN initing storage	recurrentL1	->	sigmoidL1
-TNN initing storage	sigmoidL1	->	combinerL1
-TNN initing storage	combinerL1	->	recurrentL1
-TNN initing storage	combinerL1	->	outputL
-TNN initing storage	outputL	->	softmaxL
+(15:25:35 2015-12-23)[nerv] info: TNN initing storage selectL1->recurrentL1
+(15:25:35 2015-12-23)[nerv] info: TNN initing storage recurrentL1->sigmoidL1
+(15:25:35 2015-12-23)[nerv] info: TNN initing storage sigmoidL1->combinerL1
+(15:25:35 2015-12-23)[nerv] info: TNN initing storage combinerL1->recurrentL1
+(15:25:35 2015-12-23)[nerv] info: TNN initing storage combinerL1->outputL
+(15:25:35 2015-12-23)[nerv] info: TNN initing storage outputL->softmaxL
 [SCHEDULER]: Initing TNN end.
 [LOG]LMSeqReader: opening file /home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/ptb.valid.txt.adds...
-batch_size:	10	chunk_size	15
-[SCHEDULER]: 40095 words processed Wed Nov 18 10:08:51 2015.
-	[SCHEDULER]: log prob per sample :-4.003230.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.47666 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:4.10684 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:3.41463 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12208 clock time
+[LOG]LMSeqReader:	batch_size:	10	chunk_size	15
+[LOG]LMSeqReader:	se_mode:	false
+(15:25:37 2015-12-23)[nerv] info: TNN initing storage selectL1->recurrentL1
+(15:25:37 2015-12-23)[nerv] info: TNN initing storage recurrentL1->sigmoidL1
+(15:25:37 2015-12-23)[nerv] info: TNN initing storage sigmoidL1->combinerL1
+(15:25:37 2015-12-23)[nerv] info: TNN initing storage combinerL1->recurrentL1
+(15:25:37 2015-12-23)[nerv] info: TNN initing storage combinerL1->outputL
+(15:25:37 2015-12-23)[nerv] info: TNN initing storage outputL->softmaxL
+(15:25:37 2015-12-23)[nerv] info: LMTrainer.lm_process_file_rnn: begin processing...
+[SCHEDULER]: 40095 words processed Wed Dec 23 15:25:45 2015.
+	[SCHEDULER]: log prob per sample :-3.991694.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.52286 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:7.15208 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.36437 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.15894 clock time
 [LOG]LMSeqReader: file expires, closing.
+(15:25:52 2015-12-23)[nerv] info: lmseqreader file ends, printing stats...
+al_sen_start:false
 [SCHEDULER]: Displaying result:
-[SCHEDULER]: LMResult status of rnn: <SEN_CN 3370> <W_CN 70390> <PPL_NET 10545.667125173> <PPL_OOV 10092.059293004> <LOGP -295333.54956309>
+[SCHEDULER]: LMResult status of rnn: <SEN_CN 3370> <W_CN 70390> <PPL_NET 10204.583785681> <PPL_OOV 9812.8219182096> <LOGP -294434.71934724>
 [SCHEDULER]: Doing on /home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/ptb.valid.txt.adds end.
 
 [SCHEDULER ITER1 LR1]: preparing parameters...
-[SCHEDULER ITER1 LR1]: loading parameter from file /home/slhome/txh18/workspace/nerv/play/dagL_test/params.0...
+[SCHEDULER ITER1 LR1]: loading parameter from file /home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnnh300ch15ba10slr1wc1e-06/params.0...
 reading chunk 0 from 0
-metadata: return {type="nerv.LinearTransParam",id="ltp_ih"}
+metadata: return {type="nerv.BiasParam",id="recurrentL1_bp"}
 
-reading chunk 1 from 34510155
-metadata: return {type="nerv.LinearTransParam",id="ltp_hh"}
+reading chunk 1 from 3512
+metadata: return {type="nerv.BiasParam",id="outputL_bp"}
 
-reading chunk 2 from 35545278
-metadata: return {type="nerv.LinearTransParam",id="ltp_ho"}
+reading chunk 2 from 118553
+metadata: return {type="nerv.LinearTransParam",id="recurrentL1_ltp_hh"}
 
-reading chunk 3 from 70045626
-metadata: return {type="nerv.BiasParam",id="bp_h"}
+reading chunk 3 from 1154327
+metadata: return {type="nerv.LinearTransParam",id="outputL_ltp"}
 
-reading chunk 4 from 70049129
-metadata: return {type="nerv.BiasParam",id="bp_o"}
+reading chunk 4 from 35653985
+metadata: return {type="nerv.LinearTransParam",id="selectL1_ltp"}
 
-reading chunk 5 from 70164107
+reading chunk 5 from 70164146
 [SCHEDULER ITER1 LR1]: preparing parameters end.
 [SCHEDULER ITER1 LR1]: preparing layers...
-(10:08:58 2015-11-18)[nerv] info: create layer: recurrentL1
-(10:08:58 2015-11-18)[nerv] info: create layer: sigmoidL1
-(10:08:58 2015-11-18)[nerv] info: create layer: combinerL1
-(10:08:58 2015-11-18)[nerv] info: create layer: outputL
-(10:08:58 2015-11-18)[nerv] info: create layer: softmaxL
-(10:08:58 2015-11-18)[nerv] info: create layer: selectL1
+(15:25:55 2015-12-23)[nerv] info: create layer: sigmoidL1
+(15:25:55 2015-12-23)[nerv] info: create layer: combinerL1
+(15:25:55 2015-12-23)[nerv] info: create layer: selectL1
+(15:25:55 2015-12-23)[nerv] info: Param [ltp] of layer [selectL1] found in layer_conf.paramRepo.
+(15:25:55 2015-12-23)[nerv] info: create layer: outputL
+(15:25:55 2015-12-23)[nerv] info: Param [ltp] of layer [outputL] found in layer_conf.paramRepo.
+(15:25:55 2015-12-23)[nerv] info: Param [bp] of layer [outputL] found in layer_conf.paramRepo.
+(15:25:55 2015-12-23)[nerv] info: create layer: softmaxL
+(15:25:55 2015-12-23)[nerv] info: create layer: recurrentL1
+(15:25:55 2015-12-23)[nerv] info: Param [bp] of layer [recurrentL1] found in layer_conf.paramRepo.
+(15:25:55 2015-12-23)[nerv] info: Param [ltp_hh] of layer [recurrentL1] found in layer_conf.paramRepo.
 [SCHEDULER ITER1 LR1]: preparing layers end.
 [SCHEDULER ITER1 LR1]: Generate and initing TNN ...
+(15:25:55 2015-12-23)[nerv] info: tnn(TNN) will extend storage beyond MB border for time steps 5...
 <input>	selectL1	0
 selectL1	recurrentL1	0
 recurrentL1	sigmoidL1	0
@@ -142,253 +153,289 @@ combinerL1	#dim_in:	1	#dim_out:	2	#i_conns_p:	1	#o_conns_p	2
 sigmoidL1	#dim_in:	1	#dim_out:	1	#i_conns_p:	1	#o_conns_p	1
 selectL1	#dim_in:	1	#dim_out:	1	#i_conns_p:	0	#o_conns_p	1
 softmaxL	#dim_in:	2	#dim_out:	1	#i_conns_p:	1	#o_conns_p	0
-TNN initing storage	selectL1	->	recurrentL1
-TNN initing storage	recurrentL1	->	sigmoidL1
-TNN initing storage	sigmoidL1	->	combinerL1
-TNN initing storage	combinerL1	->	recurrentL1
-TNN initing storage	combinerL1	->	outputL
-TNN initing storage	outputL	->	softmaxL
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage selectL1->recurrentL1
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage recurrentL1->sigmoidL1
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage sigmoidL1->combinerL1
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage combinerL1->recurrentL1
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage combinerL1->outputL
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage outputL->softmaxL
 [SCHEDULER ITER1 LR1]: Initing TNN end.
 ===ITERATION 1 LR 1.000000===
-[LOG]LMSeqReader: opening file /home/slhome/txh18/workspace/nerv/play/dagL_test/train_fn_shuf...
-batch_size:	10	chunk_size	15
-[SCHEDULER ITER1 LR1]: 40099 words processed Wed Nov 18 10:09:09 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-3.210428.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.47135 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.75538 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.22335 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.57185 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10319 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12114 clock time
-[SCHEDULER ITER1 LR1]: 80063 words processed Wed Nov 18 10:09:21 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-3.048713.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46917 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.75080 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.19680 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.56019 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09740 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12030 clock time
-[SCHEDULER ITER1 LR1]: 120068 words processed Wed Nov 18 10:09:33 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.984911.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.47044 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.74848 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.18711 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55472 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09624 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12070 clock time
-[SCHEDULER ITER1 LR1]: 160017 words processed Wed Nov 18 10:09:45 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.930297.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.47130 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.75352 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.20206 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55933 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09779 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12088 clock time
-[SCHEDULER ITER1 LR1]: 200138 words processed Wed Nov 18 10:09:57 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.897628.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46695 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.76538 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.23399 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.57699 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10442 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12134 clock time
-[SCHEDULER ITER1 LR1]: 240007 words processed Wed Nov 18 10:10:09 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.867407.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46510 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.73963 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.15285 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.54229 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.08908 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12042 clock time
-[SCHEDULER ITER1 LR1]: 280135 words processed Wed Nov 18 10:10:21 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.842329.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46714 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.75314 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.21984 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.57472 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10567 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12149 clock time
-[SCHEDULER ITER1 LR1]: 320080 words processed Wed Nov 18 10:10:33 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.823036.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46701 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.75169 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.20551 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.56419 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10051 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12255 clock time
-[SCHEDULER ITER1 LR1]: 360059 words processed Wed Nov 18 10:10:45 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.800986.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.47814 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.79713 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.30428 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.58719 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10865 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12425 clock time
-[SCHEDULER ITER1 LR1]: 400021 words processed Wed Nov 18 10:10:57 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.786891.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.45977 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.73850 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.17294 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55793 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09813 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12008 clock time
-[SCHEDULER ITER1 LR1]: 440102 words processed Wed Nov 18 10:11:09 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.770894.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46478 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.75843 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.22462 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.57475 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10523 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12179 clock time
-[SCHEDULER ITER1 LR1]: 480051 words processed Wed Nov 18 10:11:21 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.754795.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46079 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.74221 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.17129 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55381 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09688 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12041 clock time
-[SCHEDULER ITER1 LR1]: 520093 words processed Wed Nov 18 10:11:33 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.740832.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46013 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.74097 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.19854 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.57069 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10617 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12053 clock time
-[SCHEDULER ITER1 LR1]: 560039 words processed Wed Nov 18 10:11:45 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.725416.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.45905 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.73400 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.16478 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55572 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09740 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12013 clock time
-[SCHEDULER ITER1 LR1]: 600112 words processed Wed Nov 18 10:11:57 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.716177.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46687 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.76335 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.25973 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.58834 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.11483 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12277 clock time
-[SCHEDULER ITER1 LR1]: 640076 words processed Wed Nov 18 10:12:09 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.705623.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46173 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.74375 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.17842 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55617 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09811 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12090 clock time
-[SCHEDULER ITER1 LR1]: 680026 words processed Wed Nov 18 10:12:21 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.696685.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46080 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.73873 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.16648 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55295 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09625 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12004 clock time
-[SCHEDULER ITER1 LR1]: 720133 words processed Wed Nov 18 10:12:33 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.687998.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46041 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.73861 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.19165 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.57016 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10446 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12015 clock time
-[SCHEDULER ITER1 LR1]: 760048 words processed Wed Nov 18 10:12:45 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.676801.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.45850 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.73148 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.15910 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55561 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09577 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.11943 clock time
-[SCHEDULER ITER1 LR1]: 800117 words processed Wed Nov 18 10:12:57 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.669544.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.45975 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.74013 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.19139 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.56894 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10351 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12031 clock time
-[SCHEDULER ITER1 LR1]: 840116 words processed Wed Nov 18 10:13:09 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.659602.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46031 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.73769 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.17842 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.56008 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10197 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.12018 clock time
-[SCHEDULER ITER1 LR1]: 880037 words processed Wed Nov 18 10:13:20 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.652101.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.45781 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.73064 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.15936 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55415 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09854 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.11997 clock time
+[LOG]LMSeqReader: opening file /home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnnh300ch15ba10slr1wc1e-06/train_fn_shuf...
+[LOG]LMSeqReader:	batch_size:	10	chunk_size	15
+[LOG]LMSeqReader:	se_mode:	false
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage selectL1->recurrentL1
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage recurrentL1->sigmoidL1
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage sigmoidL1->combinerL1
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage combinerL1->recurrentL1
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage combinerL1->outputL
+(15:25:55 2015-12-23)[nerv] info: TNN initing storage outputL->softmaxL
+(15:25:55 2015-12-23)[nerv] info: LMTrainer.lm_process_file_rnn: begin processing...
+[SCHEDULER ITER1 LR1]: 40099 words processed Wed Dec 23 15:26:11 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-3.208733.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.49912 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.18861 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.10438 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.86339 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.13806 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.15891 clock time
+[SCHEDULER ITER1 LR1]: 80063 words processed Wed Dec 23 15:26:27 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-3.027452.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.50375 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.16717 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.04599 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.83912 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.12530 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.15900 clock time
+[SCHEDULER ITER1 LR1]: 120068 words processed Wed Dec 23 15:26:43 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.949047.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.49959 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.17205 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.04428 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.83331 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.12965 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.15888 clock time
+[SCHEDULER ITER1 LR1]: 160017 words processed Wed Dec 23 15:27:00 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.892670.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.52759 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.48079 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.64937 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:6.00684 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.16768 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.16836 clock time
+[SCHEDULER ITER1 LR1]: 200138 words processed Wed Dec 23 15:27:17 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.862344.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.50400 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.26080 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.23420 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.90703 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.13851 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.16026 clock time
+[SCHEDULER ITER1 LR1]: 240007 words processed Wed Dec 23 15:27:34 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.832988.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.50224 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.27449 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.24373 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.89637 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.13873 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.15986 clock time
+[SCHEDULER ITER1 LR1]: 280135 words processed Wed Dec 23 15:27:51 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.807892.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.52736 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.50277 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.71085 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:6.03449 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.17865 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.16944 clock time
+[SCHEDULER ITER1 LR1]: 320080 words processed Wed Dec 23 15:28:07 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.787610.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.47566 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.02338 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:14.73258 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.75188 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10406 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.14869 clock time
+[SCHEDULER ITER1 LR1]: 360059 words processed Wed Dec 23 15:28:23 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.765522.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46910 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:5.98256 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:14.64817 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.72921 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09774 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.14636 clock time
+[SCHEDULER ITER1 LR1]: 400021 words processed Wed Dec 23 15:28:39 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.751868.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46969 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:5.98096 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:14.64490 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.72892 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09642 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.14590 clock time
+[SCHEDULER ITER1 LR1]: 440102 words processed Wed Dec 23 15:28:55 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.736409.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.47132 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.00369 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:14.69775 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.74976 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10222 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.14619 clock time
+[SCHEDULER ITER1 LR1]: 480051 words processed Wed Dec 23 15:29:11 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.721181.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46899 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:5.98351 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:14.64798 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.72954 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09617 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.14592 clock time
+[SCHEDULER ITER1 LR1]: 520093 words processed Wed Dec 23 15:29:27 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.708133.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.47288 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.01261 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:14.72172 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.75420 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10711 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.14766 clock time
+[SCHEDULER ITER1 LR1]: 560039 words processed Wed Dec 23 15:29:43 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.693347.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.47246 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.00098 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:14.68805 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.74210 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09885 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.14709 clock time
+[SCHEDULER ITER1 LR1]: 600112 words processed Wed Dec 23 15:29:59 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.684825.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.47372 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.03642 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:14.75985 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.76671 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10646 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.14797 clock time
+[SCHEDULER ITER1 LR1]: 640076 words processed Wed Dec 23 15:30:16 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.674873.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.51025 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.37618 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.42601 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.94153 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.15211 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.16617 clock time
+[SCHEDULER ITER1 LR1]: 680026 words processed Wed Dec 23 15:30:33 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.666825.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.50876 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.36958 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.46533 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.96944 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.15677 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.16815 clock time
+[SCHEDULER ITER1 LR1]: 720133 words processed Wed Dec 23 15:30:50 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.658816.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.49595 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.25148 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.18774 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.88182 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.13916 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.15690 clock time
+[SCHEDULER ITER1 LR1]: 760048 words processed Wed Dec 23 15:31:07 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.648532.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.50178 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.32493 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.32939 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.92035 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.14429 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.16224 clock time
+[SCHEDULER ITER1 LR1]: 800117 words processed Wed Dec 23 15:31:24 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.642086.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.50275 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.30792 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.31499 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.91857 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.15170 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.16169 clock time
+[SCHEDULER ITER1 LR1]: 840116 words processed Wed Dec 23 15:31:41 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.633060.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.51405 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.40662 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.48276 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.95914 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.15308 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.16813 clock time
+[SCHEDULER ITER1 LR1]: 880037 words processed Wed Dec 23 15:31:58 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.626273.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.49958 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.27819 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:15.22222 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:5.87408 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.14477 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.15965 clock time
 [LOG]LMSeqReader: file expires, closing.
+(15:32:02 2015-12-23)[nerv] info: lmseqreader file ends, printing stats...
+al_sen_start:false
 [SCHEDULER ITER1 LR1]: Displaying result:
-[SCHEDULER ITER1 LR1]: LMResult status of rnn: <SEN_CN 42068> <W_CN 887521> <PPL_NET 512.01508977938> <PPL_OOV 447.19970345812> <LOGP -2463877.0452922>
-[SCHEDULER ITER1 LR1]: Doing on /home/slhome/txh18/workspace/nerv/play/dagL_test/train_fn_shuf end.
+[SCHEDULER ITER1 LR1]: LMResult status of rnn: <SEN_CN 42068> <W_CN 887521> <PPL_NET 483.24236261194> <PPL_OOV 421.50130390255> <LOGP -2439984.2055128>
+[SCHEDULER ITER1 LR1]: Doing on /home/slhome/txh18/workspace/ptb/EXP-nerv/rnnlm_tnnh300ch15ba10slr1wc1e-06/train_fn_shuf end.
 [SCHEDULER ITER1 LR1]: shuffling training file
 ===PEEK ON TEST 1===
 [LOG]LMSeqReader: opening file /home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/ptb.test.txt.adds...
-batch_size:	10	chunk_size	15
-[SCHEDULER ITER1 LR1]: 40087 words processed Wed Nov 18 10:13:30 2015.
-	[SCHEDULER ITER1 LR1]: log prob per sample :-2.504076.
-	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46941 clock time
-	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.75798 clock time
-	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:3.45029 clock time
-	 [global_conf.timer]: time spent on tnn_afterprocess:0.11464 clock time
+[LOG]LMSeqReader:	batch_size:	10	chunk_size	15
+[LOG]LMSeqReader:	se_mode:	false
+(15:32:05 2015-12-23)[nerv] info: TNN initing storage selectL1->recurrentL1
+(15:32:05 2015-12-23)[nerv] info: TNN initing storage recurrentL1->sigmoidL1
+(15:32:05 2015-12-23)[nerv] info: TNN initing storage sigmoidL1->combinerL1
+(15:32:05 2015-12-23)[nerv] info: TNN initing storage combinerL1->recurrentL1
+(15:32:05 2015-12-23)[nerv] info: TNN initing storage combinerL1->outputL
+(15:32:05 2015-12-23)[nerv] info: TNN initing storage outputL->softmaxL
+(15:32:05 2015-12-23)[nerv] info: LMTrainer.lm_process_file_rnn: begin processing...
+[SCHEDULER ITER1 LR1]: 40087 words processed Wed Dec 23 15:32:13 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.490319.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.52150 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:6.47313 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:7.29086 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.15853 clock time
 [LOG]LMSeqReader: file expires, closing.
+(15:32:21 2015-12-23)[nerv] info: lmseqreader file ends, printing stats...
+al_sen_start:false
 [SCHEDULER ITER1 LR1]: Displaying result:
-[SCHEDULER ITER1 LR1]: LMResult status of rnn: <SEN_CN 3761> <W_CN 78669> <PPL_NET 370.53246252795> <PPL_OOV 323.54357826836> <LOGP -206893.75941108&