Merge pull request #12 from cloudygoose/txh18/rnnlm

add atomicAdd for cukernel

12 files changed, 18870 insertions, 3878 deletions

diff --git a/nerv/examples/lmptb/lm_trainer.lua b/nerv/examples/lmptb/lm_trainer.lua
index 44862dc..62d8b50 100644
--- a/nerv/examples/lmptb/lm_trainer.lua
+++ b/nerv/examples/lmptb/lm_trainer.lua
@@ -15,28 +15,32 @@ function LMTrainer.lm_process_file(global_conf, fn, tnn, do_train)
     reader:open_file(fn)
     local result = nerv.LMResult(global_conf, global_conf.vocab)
     result:init("rnn")
-    
+        
     global_conf.timer:flush()
     tnn:flush_all() --caution: will also flush the inputs from the reader!
 
     local next_log_wcn = global_conf.log_w_num
+    local neto_bakm = global_conf.mmat_type(global_conf.batch_size, 1) --space backup matrix for network output
 
     while (1) do
         global_conf.timer:tic('most_out_loop_lmprocessfile')
 
         local r, feeds
-
-        r, feeds = tnn:getFeedFromReader(reader)
-        if (r == false) then break end
+        global_conf.timer:tic('tnn_beforeprocess')
+        r, feeds = tnn:getfeed_from_reader(reader)
+        if r == false then 
+            break 
+        end
     
         for t = 1, global_conf.chunk_size do
             tnn.err_inputs_m[t][1]:fill(1)
             for i = 1, global_conf.batch_size do
-                if (bit.band(feeds.flags_now[t][i], nerv.TNN.FC.HAS_LABEL) == 0) then
+                if bit.band(feeds.flags_now[t][i], nerv.TNN.FC.HAS_LABEL) == 0 then
                     tnn.err_inputs_m[t][1][i - 1][0] = 0
                 end
             end
         end
+        global_conf.timer:toc('tnn_beforeprocess')
 
         --[[
         for j = 1, global_conf.chunk_size, 1 do
@@ -50,24 +54,28 @@ function LMTrainer.lm_process_file(global_conf, fn, tnn, do_train)
 
         tnn:net_propagate()
  
-        if (do_train == true) then
+        if do_train == true then
             tnn:net_backpropagate(false) 
             tnn:net_backpropagate(true)
         end
- 
+
+        global_conf.timer:tic('tnn_afterprocess')
         for t = 1, global_conf.chunk_size, 1 do
+            tnn.outputs_m[t][1]:copy_toh(neto_bakm)
             for i = 1, global_conf.batch_size, 1 do
                 if (feeds.labels_s[t][i] ~= global_conf.vocab.null_token) then
-                    result:add("rnn", feeds.labels_s[t][i], math.exp(tnn.outputs_m[t][1][i - 1][0]))
+                    --result:add("rnn", feeds.labels_s[t][i], math.exp(tnn.outputs_m[t][1][i - 1][0]))
+                    result:add("rnn", feeds.labels_s[t][i], math.exp(neto_bakm[i - 1][0]))
                 end
             end            
         end
+        tnn:move_right_to_nextmb({0}) --only copy for time 0
+        global_conf.timer:toc('tnn_afterprocess')
 
-        tnn:moveRightToNextMB()
         global_conf.timer:toc('most_out_loop_lmprocessfile')
 
         --print log
-        if (result["rnn"].cn_w > next_log_wcn) then
+        if result["rnn"].cn_w > next_log_wcn then
             next_log_wcn = next_log_wcn + global_conf.log_w_num
             printf("%s %d words processed %s.\n", global_conf.sche_log_pre, result["rnn"].cn_w, os.date()) 
             printf("\t%s log prob per sample :%f.\n", global_conf.sche_log_pre, result:logp_sample("rnn"))
diff --git a/nerv/examples/lmptb/lmptb/layer/select_linear.lua b/nerv/examples/lmptb/lmptb/layer/select_linear.lua
index 672b7e2..e96296f 100644
--- a/nerv/examples/lmptb/lmptb/layer/select_linear.lua
+++ b/nerv/examples/lmptb/lmptb/layer/select_linear.lua
@@ -30,12 +30,13 @@ function SL:init(batch_size)
 end
 
 function SL:update(bp_err, input, output)
-    --for i = 1, input[1]:ncol(), 1 do
-    --    if (input[1][0][i - 1] ~= 0) then
-    --        local word_vec = self.ltp.trans[input[1][0][i - 1]]
-            --word_vec:add(word_vec, bp_err[1][i - 1], 1, - self.gconf.lrate / self.gconf.batch_size)
-    --    end
+    --use this to produce reproducable result
+    --for i = 1, input[1]:nrow(), 1 do
+    --    local word_vec = self.ltp.trans[input[1][i - 1][0]]
+    --    word_vec:add(word_vec, bp_err[1][i - 1], 1, - self.gconf.lrate / self.gconf.batch_size)
     --end 
+    
+    --I tried the update_select_rows kernel which uses atomicAdd, but it generates unreproducable result
     self.ltp.trans:update_select_rows(bp_err[1], input[1]:trans(), - self.gconf.lrate / self.gconf.batch_size, 0)
     self.ltp.trans:add(self.ltp.trans, self.ltp.trans, 1.0, - self.gconf.lrate * self.gconf.wcost / self.gconf.batch_size)
 end
diff --git a/nerv/examples/lmptb/lmptb/lmseqreader.lua b/nerv/examples/lmptb/lmptb/lmseqreader.lua
index e0dcd95..cc805a4 100644
--- a/nerv/examples/lmptb/lmptb/lmseqreader.lua
+++ b/nerv/examples/lmptb/lmptb/lmseqreader.lua
@@ -30,6 +30,13 @@ function LMReader:open_file(fn)
     for i = 1, self.batch_size, 1 do
         self.streams[i] = {["store"] = {}, ["head"] = 1, ["tail"] = 0}
     end
+    
+    self.bak_inputs_m = {} --backup MMatrix for temporary storey(then copy to TNN CuMatrix)
+    for j = 1, self.chunk_size, 1 do
+        self.bak_inputs_m[j] = {}
+        self.bak_inputs_m[j][1] = self.gconf.mmat_type(self.batch_size, 1)
+        self.bak_inputs_m[j][2] = self.gconf.mmat_type(self.batch_size, self.vocab:size()) --since MMatrix does not yet have fill, this m[j][2] is not used
+    end
 end
    
 --id: int
@@ -78,7 +85,7 @@ function LMReader:get_batch(feeds)
     local labels_s = feeds.labels_s
     for i = 1, self.chunk_size, 1 do
         inputs_s[i] = {}
-        labels_s[i] = {}
+        labels_s[i] = {} 
     end
 
     local inputs_m = feeds.inputs_m --port 1 : word_id, port 2 : label
@@ -86,20 +93,24 @@ function LMReader:get_batch(feeds)
     local flagsPack = feeds.flagsPack_now
 
     local got_new = false
+    for j = 1, self.chunk_size, 1 do
+        inputs_m[j][2]:fill(0)
+    end
     for i = 1, self.batch_size, 1 do
         local st = self.streams[i]
         for j = 1, self.chunk_size, 1 do
             flags[j][i] = 0
             self:refresh_stream(i)
-            if (st.store[st.head] ~= nil) then
+            if st.store[st.head] ~= nil then
                 inputs_s[j][i] = st.store[st.head]
-                inputs_m[j][1][i - 1][0] = self.vocab:get_word_str(st.store[st.head]).id - 1
+                --inputs_m[j][1][i - 1][0] = self.vocab:get_word_str(st.store[st.head]).id - 1
+                self.bak_inputs_m[j][1][i - 1][0] = self.vocab:get_word_str(st.store[st.head]).id - 1
             else
                 inputs_s[j][i] = self.vocab.null_token
-                inputs_m[j][1][i - 1][0] = 0
+                --inputs_m[j][1][i - 1][0] = 0
+                self.bak_inputs_m[j][1][i - 1][0] = 0
             end
-            inputs_m[j][2][i - 1]:fill(0)
-            if (st.store[st.head + 1] ~= nil) then
+            if st.store[st.head + 1] ~= nil then
                 labels_s[j][i] = st.store[st.head + 1]
                 inputs_m[j][2][i - 1][self.vocab:get_word_str(st.store[st.head + 1]).id - 1] = 1
             else
@@ -116,12 +127,12 @@ function LMReader:get_batch(feeds)
                 got_new = true
                 st.store[st.head] = nil
                 st.head = st.head + 1
-                if (labels_s[j][i] == self.vocab.sen_end_token) then
+                if labels_s[j][i] == self.vocab.sen_end_token then
                     flags[j][i] = bit.bor(flags[j][i], nerv.TNN.FC.SEQ_END)
                     st.store[st.head] = nil --sentence end is passed
                     st.head = st.head + 1
                 end
-                if (inputs_s[j][i] == self.vocab.sen_end_token) then
+                if inputs_s[j][i] == self.vocab.sen_end_token then
                     flags[j][i] = bit.bor(flags[j][i], nerv.TNN.FC.SEQ_START)
                 end
             end 
@@ -133,6 +144,7 @@ function LMReader:get_batch(feeds)
         for i = 1, self.batch_size, 1 do
             flagsPack[j] = bit.bor(flagsPack[j], flags[j][i])
         end
+        inputs_m[j][1]:copy_fromh(self.bak_inputs_m[j][1])
     end
 
     if (got_new == false) then
diff --git a/nerv/examples/lmptb/logs/LOG-tnn-h300 b/nerv/examples/lmptb/logs/LOG-tnn-h300
new file mode 100644
index 0000000..77fd612
--- /dev/null
+++ b/nerv/examples/lmptb/logs/LOG-tnn-h300
@@ -0,0 +1,9372 @@
+Greetings
+[SCHEDULER]: applying arg[2](global_conf.hidden_size=300)...
+[SCHEDULER]: printing global_conf...
+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
+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
+log_w_num	40000
+work_dir	/home/slhome/txh18/workspace/nerv/play/dagL_test
+batch_size	10
+hidden_size	300
+timer	nerv.Timer
+sche_log_pre	[SCHEDULER]:
+nn_act_default	0
+max_iter	35
+valid_fn	/home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/ptb.valid.txt.adds
+lrate	1
+momentum	0
+wcost	1e-05
+chunk_size	15
+cumat_type	table: 0x40935010
+[SCHEDULER]: printing training scheduling options...
+lr_half	false
+start_iter	-1
+ppl_last	100000
+[SCHEDULER]: printing training scheduling end.
+[SCHEDULER]: creating work_dir...
+[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...
+===INITIAL VALIDATION===
+[SCHEDULER]: preparing parameters...
+[SCHEDULER]: loading parameter from file /home/slhome/txh18/workspace/nerv/play/dagL_test/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
+[SCHEDULER]: preparing layers end.
+[SCHEDULER]: Generate and initing TNN ...
+<input>	selectL1	0
+selectL1	recurrentL1	0
+recurrentL1	sigmoidL1	0
+sigmoidL1	combinerL1	0
+combinerL1	recurrentL1	1
+combinerL1	outputL	0
+outputL	softmaxL	0
+<input>	softmaxL	0
+softmaxL	<output>	0
+recurrentL1	#dim_in:	2	#dim_out:	1	#i_conns_p:	2	#o_conns_p	1
+outputL	#dim_in:	1	#dim_out:	1	#i_conns_p:	1	#o_conns_p	1
+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
+[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: file expires, closing.
+[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]: 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...
+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 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
+[SCHEDULER ITER1 LR1]: preparing layers end.
+[SCHEDULER ITER1 LR1]: Generate and initing TNN ...
+<input>	selectL1	0
+selectL1	recurrentL1	0
+recurrentL1	sigmoidL1	0
+sigmoidL1	combinerL1	0
+combinerL1	recurrentL1	1
+combinerL1	outputL	0
+outputL	softmaxL	0
+<input>	softmaxL	0
+softmaxL	<output>	0
+recurrentL1	#dim_in:	2	#dim_out:	1	#i_conns_p:	2	#o_conns_p	1
+outputL	#dim_in:	1	#dim_out:	1	#i_conns_p:	1	#o_conns_p	1
+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
+[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: file expires, closing.
+[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]: 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: file expires, closing.
+[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>
+[SCHEDULER ITER1 LR1]: Doing on /home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/ptb.test.txt.adds end.
+===VALIDATION 1===
+[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 ITER1 LR1]: 40095 words processed Wed Nov 18 10:13:39 2015.
+	[SCHEDULER ITER1 LR1]: log prob per sample :-2.547314.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46703 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.75630 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:3.44636 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.11481 clock time
+[LOG]LMSeqReader: file expires, closing.
+[SCHEDULER ITER1 LR1]: Displaying result:
+[SCHEDULER ITER1 LR1]: LMResult status of rnn: <SEN_CN 3370> <W_CN 70390> <PPL_NET 369.92944180373> <PPL_OOV 331.71274183319> <LOGP -185931.4164841>
+[SCHEDULER ITER1 LR1]: Doing on /home/slhome/txh18/workspace/nerv/nerv/nerv/examples/lmptb/PTBdata/ptb.valid.txt.adds end.
+[SCHEDULER ITER1 LR1]: PPL improves, saving net to file /home/slhome/txh18/workspace/nerv/play/dagL_test/params.1...
+
+[SCHEDULER ITER2 LR1]: preparing parameters...
+[SCHEDULER ITER2 LR1]: loading parameter from file /home/slhome/txh18/workspace/nerv/play/dagL_test/params.1...
+reading chunk 0 from 0
+metadata: return {type="nerv.LinearTransParam",id="ltp_hh"}
+
+reading chunk 1 from 1076633
+metadata: return {type="nerv.BiasParam",id="bp_h"}
+
+reading chunk 2 from 1080289
+metadata: return {type="nerv.LinearTransParam",id="ltp_ho"}
+
+reading chunk 3 from 35608824
+metadata: return {type="nerv.BiasParam",id="bp_o"}
+
+reading chunk 4 from 35725140
+metadata: return {type="nerv.LinearTransParam",id="ltp_ih"}
+
+reading chunk 5 from 70244205
+[SCHEDULER ITER2 LR1]: preparing parameters end.
+[SCHEDULER ITER2 LR1]: preparing layers...
+(10:13:48 2015-11-18)[nerv] info: create layer: recurrentL1
+(10:13:48 2015-11-18)[nerv] info: create layer: sigmoidL1
+(10:13:48 2015-11-18)[nerv] info: create layer: combinerL1
+(10:13:48 2015-11-18)[nerv] info: create layer: outputL
+(10:13:48 2015-11-18)[nerv] info: create layer: softmaxL
+(10:13:48 2015-11-18)[nerv] info: create layer: selectL1
+[SCHEDULER ITER2 LR1]: preparing layers end.
+[SCHEDULER ITER2 LR1]: Generate and initing TNN ...
+<input>	selectL1	0
+selectL1	recurrentL1	0
+recurrentL1	sigmoidL1	0
+sigmoidL1	combinerL1	0
+combinerL1	recurrentL1	1
+combinerL1	outputL	0
+outputL	softmaxL	0
+<input>	softmaxL	0
+softmaxL	<output>	0
+recurrentL1	#dim_in:	2	#dim_out:	1	#i_conns_p:	2	#o_conns_p	1
+outputL	#dim_in:	1	#dim_out:	1	#i_conns_p:	1	#o_conns_p	1
+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
+[SCHEDULER ITER2 LR1]: Initing TNN end.
+===ITERATION 2 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 ITER2 LR1]: 40092 words processed Wed Nov 18 10:13:59 2015.
+	[SCHEDULER ITER2 LR1]: log prob per sample :-2.541969.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46836 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.72598 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.22414 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.56508 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09968 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.11795 clock time
+[SCHEDULER ITER2 LR1]: 80099 words processed Wed Nov 18 10:14:11 2015.
+	[SCHEDULER ITER2 LR1]: log prob per sample :-2.535649.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46987 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.73527 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.21641 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55211 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09413 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.11941 clock time
+[SCHEDULER ITER2 LR1]: 120004 words processed Wed Nov 18 10:14:23 2015.
+	[SCHEDULER ITER2 LR1]: log prob per sample :-2.527511.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46606 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.72308 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.19836 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.54952 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09336 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.11779 clock time
+[SCHEDULER ITER2 LR1]: 160114 words processed Wed Nov 18 10:14:35 2015.
+	[SCHEDULER ITER2 LR1]: log prob per sample :-2.522344.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46532 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.72510 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.22327 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.56668 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.10154 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.11830 clock time
+[SCHEDULER ITER2 LR1]: 200066 words processed Wed Nov 18 10:14:46 2015.
+	[SCHEDULER ITER2 LR1]: log prob per sample :-2.517881.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46174 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.71860 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.18739 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55076 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09280 clock time
+	 [global_conf.timer]: time spent on tnn_afterprocess:0.11754 clock time
+[SCHEDULER ITER2 LR1]: 240045 words processed Wed Nov 18 10:14:58 2015.
+	[SCHEDULER ITER2 LR1]: log prob per sample :-2.512076.
+	 [global_conf.timer]: time spent on tnn_beforeprocess:0.46366 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_propagate:2.72754 clock time
+	 [global_conf.timer]: time spent on most_out_loop_lmprocessfile:10.21275 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_update:4.55625 clock time
+	 [global_conf.timer]: time spent on tnn_actual_layer_backpropagate:2.09893 clock time