Merge branch 'develop'

add logging support to replace print

dreamplace/BasicPlace.py

@@ -15,6 +15,7 @@
     import _pickle as pickle
 import re 
 import numpy as np 
+import logging
 import torch 
 import torch.nn as nn
 import dreamplace.ops.move_boundary.move_boundary as move_boundary 
@@ -58,7 +59,7 @@ def __init__(self, pos, params, placedb, device):
         if np.amin(placedb.net_weights) != np.amax(placedb.net_weights): # weights are meaningful 
             self.net_weights = torch.from_numpy(placedb.net_weights).to(device)
         else: # an empty tensor 
-            print("[I] net weights are all the same, ignored")
+            logging.warning("net weights are all the same, ignored")
             self.net_weights = torch.Tensor().to(device)
 
         self.net_mask_all = torch.from_numpy(np.ones(placedb.num_nets, dtype=np.uint8)).to(device) # all nets included 
@@ -140,12 +141,12 @@ def __init__(self, params, placedb):
         torch.manual_seed(params.random_seed)
         super(BasicPlace, self).__init__()
 
-        #tt = time.time()
+        tt = time.time()
         self.init_pos = np.zeros(placedb.num_nodes*2, dtype=placedb.dtype)
         # x position 
         self.init_pos[0:placedb.num_physical_nodes] = placedb.node_x
         if params.global_place_flag and params.random_center_init_flag: # move to center of layout 
-            print("[I] move cells to the center of layout with random noise")
+            logging.info("move cells to the center of layout with random noise")
             self.init_pos[0:placedb.num_movable_nodes] = np.random.normal(loc=(placedb.xl*1.0+placedb.xh*1.0)/2, scale=(placedb.xh-placedb.xl)*0.001, size=placedb.num_movable_nodes)
         #self.init_pos[0:placedb.num_movable_nodes] = init_x[0:placedb.num_movable_nodes]*0.01 + (placedb.xl+placedb.xh)/2
         # y position 
@@ -158,26 +159,26 @@ def __init__(self, params, placedb):
             self.init_pos[placedb.num_physical_nodes:placedb.num_nodes] = np.random.uniform(low=placedb.xl, high=placedb.xh-placedb.node_size_x[-placedb.num_filler_nodes], size=placedb.num_filler_nodes)
             self.init_pos[placedb.num_nodes+placedb.num_physical_nodes:placedb.num_nodes*2] = np.random.uniform(low=placedb.yl, high=placedb.yh-placedb.node_size_y[-placedb.num_filler_nodes], size=placedb.num_filler_nodes)
 
-        #print("prepare init_pos takes %.2f seconds" % (time.time()-tt))
+        logging.debug("prepare init_pos takes %.2f seconds" % (time.time()-tt))
 
         self.device = torch.device("cuda" if params.gpu else "cpu")
 
         # position should be parameter 
         # must be defined in BasicPlace 
-        #tt = time.time()
+        tt = time.time()
         self.pos = nn.ParameterList([nn.Parameter(torch.from_numpy(self.init_pos).to(self.device))])
-        #print("build pos takes %.2f seconds" % (time.time()-tt))
+        logging.debug("build pos takes %.2f seconds" % (time.time()-tt))
         # shared data on device for building ops  
         # I do not want to construct the data from placedb again and again for each op 
-        #tt = time.time()
+        tt = time.time()
         self.data_collections = PlaceDataCollection(self.pos, params, placedb, self.device)
-        #print("build data_collections takes %.2f seconds" % (time.time()-tt))
+        logging.debug("build data_collections takes %.2f seconds" % (time.time()-tt))
         # similarly I wrap all ops 
-        #tt = time.time()
+        tt = time.time()
         self.op_collections = PlaceOpCollection()
-        #print("build op_collections takes %.2f seconds" % (time.time()-tt))
+        logging.debug("build op_collections takes %.2f seconds" % (time.time()-tt))
 
-        #tt = time.time()
+        tt = time.time()
         # position to pin position
         self.op_collections.pin_pos_op = self.build_pin_pos(params, placedb, self.data_collections, self.device)
         # bound nodes to layout region 
@@ -198,7 +199,7 @@ def __init__(self, params, placedb):
         # can only read once 
         self.read_lut_flag = True
 
-        #print("build BasicPlace ops takes %.2f seconds" % (time.time()-tt))
+        logging.debug("build BasicPlace ops takes %.2f seconds" % (time.time()-tt))
 
     def __call__(self, params, placedb):
         """
@@ -279,8 +280,8 @@ def build_rmst_wl(self, params, placedb, pin_pos_op, device):
 
         POWVFILE = os.path.abspath(os.path.join(os.path.dirname(__file__), "../../thirdparty/flute-3.1/POWV9.dat"))
         POSTFILE = os.path.abspath(os.path.join(os.path.dirname(__file__), "../../thirdparty/flute-3.1/POST9.dat"))
-        print("POWVFILE = %s" % (POWVFILE))
-        print("POSTFILE = %s" % (POSTFILE))
+        logging.info("POWVFILE = %s" % (POWVFILE))
+        logging.info("POSTFILE = %s" % (POSTFILE))
         wirelength_for_pin_op = rmst_wl.RMSTWL(
                 flat_netpin=torch.from_numpy(placedb.flat_net2pin_map).to(device), 
                 netpin_start=torch.from_numpy(placedb.flat_net2pin_start_map).to(device),
@@ -396,4 +397,4 @@ def plot(self, params, placedb, iteration, pos):
         if isinstance(pos, np.ndarray):
             pos = torch.from_numpy(pos)
         self.op_collections.draw_place_op(pos, figname)
-        print("[I] plotting to %s takes %.3f seconds" % (figname, time.time()-tt))
+        logging.info("plotting to %s takes %.3f seconds" % (figname, time.time()-tt))

dreamplace/ConjugateGradientOptimizer.py

@@ -10,6 +10,7 @@
 import time 
 import pickle 
 import numpy as np 
+import logging
 import torch 
 from torch.optim.optimizer import Optimizer, required
 import pdb 
@@ -74,7 +75,7 @@ def step(self, closure=None):
                     alpha_k = torch.tensor(group['lr'], dtype=d_k.dtype, device=d_k.device)
                     alpha_k, line_search_count, obj_at_alpha_k[0] = line_search_fn(xk=p.data, pk=d_k, gfk=g_k, fk=None, alpha0=alpha_k)
                     group['obj_eval_count'] += line_search_count
-                    print("alpha_k = %g, line_search_count = %d, obj_at_alpha_k = %g, obj_eval_count = %d" % (alpha_k, line_search_count, obj_at_alpha_k[0], group['obj_eval_count']))
+                    logging.debug("alpha_k = %g, line_search_count = %d, obj_at_alpha_k = %g, obj_eval_count = %d" % (alpha_k, line_search_count, obj_at_alpha_k[0], group['obj_eval_count']))
                 p.data.add_(alpha_k.mul(d_k))
 
                 g_k_1.data.copy_(g_k)

dreamplace/EvalMetrics.py

@@ -34,7 +34,7 @@ def __str__(self):
         """
         content = ""
         if self.iteration is not None:
-            content = "[I] iteration %4d" % (self.iteration)
+            content = "iteration %4d" % (self.iteration)
         if self.wirelength is not None:
             content += ", wirelength %.3E" % (self.wirelength)
         if self.density is not None: 

dreamplace/NesterovAcceleratedGradientOptimizer.py

@@ -118,20 +118,20 @@ def step(self, closure=None):
                     alpha_kp1 = torch.dist(v_kp1.data, v_k.data, p=2) / torch.dist(g_kp1.data, g_k.data, p=2) 
                     backtrack_cnt += 1
                     group['obj_eval_count'] += 1
-                    #print("\t\talpha_kp1 %.3f ms" % ((time.time()-tt)*1000))
+                    #logging.debug("\t\talpha_kp1 %.3f ms" % ((time.time()-tt)*1000))
                     #torch.cuda.synchronize()
-                    #print(prof)
+                    #logging.debug(prof)
 
-                    #print("alpha_kp1 = %g, line_search_count = %d, obj_eval_count = %d" % (alpha_kp1, backtrack_cnt, group['obj_eval_count']))
-                    #print("|g_k| = %.6E, |g_kp1| = %.6E" % (g_k.norm(p=2), g_kp1.norm(p=2)))
+                    #logging.debug("alpha_kp1 = %g, line_search_count = %d, obj_eval_count = %d" % (alpha_kp1, backtrack_cnt, group['obj_eval_count']))
+                    #logging.debug("|g_k| = %.6E, |g_kp1| = %.6E" % (g_k.norm(p=2), g_kp1.norm(p=2)))
                     if alpha_kp1 > 0.95*alpha_k or backtrack_cnt >= max_backtrack_cnt:
                         alpha_k.data.copy_(alpha_kp1.data)
                         break 
                     else:
                         alpha_k.data.copy_(alpha_kp1.data)
                 if v_k.is_cuda: 
                     torch.cuda.synchronize()
-                #print("\tline search %.3f ms" % ((time.time()-ttt)*1000))
+                #logging.debug("\tline search %.3f ms" % ((time.time()-ttt)*1000))
 
                 v_k_1.data.copy_(v_k.data)
                 g_k_1.data.copy_(g_k.data)

dreamplace/NonLinearPlace.py

@@ -10,6 +10,7 @@
 import time 
 import pickle
 import numpy as np 
+import logging
 import torch 
 import gzip 
 if sys.version_info[0] < 3: 
@@ -80,7 +81,7 @@ def __call__(self, params, placedb):
                 else:
                     assert 0, "unknown optimizer %s" % (optimizer_name)
 
-                print("[I] use %s optimizer" % (optimizer_name))
+                logging.info("use %s optimizer" % (optimizer_name))
                 model.train()
                 learning_rate = model.learning_rate
                 # defining evaluation ops 
@@ -93,12 +94,12 @@ def __call__(self, params, placedb):
 
                 if iteration == 0: 
                     if params.gp_noise_ratio > 0.0: 
-                        print("[I] add %g%% noise" % (params.gp_noise_ratio*100))
+                        logging.info("add %g%% noise" % (params.gp_noise_ratio*100))
                         model.op_collections.noise_op(model.data_collections.pos[0], params.gp_noise_ratio)
 
                 if params.gpu: 
                     torch.cuda.synchronize()
-                print("[I] %s initialization takes %g seconds" % (optimizer_name, (time.time()-tt)))
+                logging.info("%s initialization takes %g seconds" % (optimizer_name, (time.time()-tt)))
 
                 for step in range(model.iteration):
                     # metric for this iteration 
@@ -112,12 +113,12 @@ def __call__(self, params, placedb):
 
                     if torch.eq(model.density_weight, 0.0):
                         model.initialize_density_weight(params, placedb)
-                        print("[I] density_weight = %.6E" % (model.density_weight.data))
+                        logging.info("density_weight = %.6E" % (model.density_weight.data))
 
                     optimizer.zero_grad()
                     #t1 = time.time()
                     cur_metric.evaluate(placedb, eval_ops, model.data_collections.pos[0])
-                    #print("evaluation %.3f ms" % ((time.time()-t1)*1000))
+                    #logging.debug("evaluation %.3f ms" % ((time.time()-t1)*1000))
                     #t2 = time.time()
                     # update density weight 
                     # gradually reduce gamma to tradeoff smoothness and accuracy 
@@ -126,7 +127,7 @@ def __call__(self, params, placedb):
                         model.op_collections.update_gamma_op(step, cur_metric.overflow)
                     cur_metric.density_weight = model.density_weight.data
                     cur_metric.gamma = model.gamma.data
-                    #print("update density weight %.3f ms" % ((time.time()-t2)*1000))
+                    #logging.debug("update density weight %.3f ms" % ((time.time()-t2)*1000))
 
                     # as nesterov requires line search, we cannot follow the convention of other solvers
                     if optimizer_name.lower() in ["sgd", "adam", "sgd_momentum", "sgd_nesterov", "cg"]: 
@@ -136,38 +137,38 @@ def __call__(self, params, placedb):
 
                     # stopping criteria 
                     if iteration > 100 and ((cur_metric.overflow < params.stop_overflow and cur_metric.hpwl > metrics[-2].hpwl) or cur_metric.max_density < 1.0):
-                        print("[D] stopping criteria: %d > 100 and (( %g < 0.1 and %g > %g ) or %g < 1.0)" % (iteration, cur_metric.overflow, cur_metric.hpwl, metrics[-2].hpwl, cur_metric.max_density))
+                        logging.debug("stopping criteria: %d > 100 and (( %g < 0.1 and %g > %g ) or %g < 1.0)" % (iteration, cur_metric.overflow, cur_metric.hpwl, metrics[-2].hpwl, cur_metric.max_density))
                         break 
 
                     # update learning rate 
                     for param_group in optimizer.param_groups:
                         param_group['lr'] = learning_rate
 
-                    print(cur_metric)
+                    logging.info(cur_metric)
                     # plot placement 
                     if params.plot_flag and iteration % 100 == 0: 
                         cur_pos = self.pos[0].data.clone().cpu().numpy()
                         self.plot(params, placedb, iteration, cur_pos)
 
                     t3 = time.time()
                     optimizer.step()
-                    print("[I] optimizer step %.3f ms" % ((time.time()-t3)*1000))
+                    logging.info("optimizer step %.3f ms" % ((time.time()-t3)*1000))
 
                     iteration += 1
 
-                    print("[I] full step %.3f ms" % ((time.time()-t0)*1000))
+                    logging.info("full step %.3f ms" % ((time.time()-t0)*1000))
 
-                print("[I] optimizer %s takes %.3f seconds" % (optimizer_name, time.time()-tt))
+                logging.info("optimizer %s takes %.3f seconds" % (optimizer_name, time.time()-tt))
 
         # legalization 
         if params.legalize_flag:
             tt = time.time()
             self.pos[0].data.copy_(self.op_collections.greedy_legalize_op(self.pos[0]))
-            print("[I] legalization takes %.3f seconds" % (time.time()-tt))
+            logging.info("legalization takes %.3f seconds" % (time.time()-tt))
 
         # detailed placement 
         if params.detailed_place_flag: 
-            print("[W] detailed placement NOT implemented yet, skipped")
+            logging.warning("detailed placement NOT implemented yet, skipped")
 
         # save results 
         cur_pos = self.pos[0].data.clone().cpu().numpy()