Added logging instead of print

SWESimulators/Common.py

@@ -27,6 +27,7 @@ import time
 import re
 import io
 import hashlib
+import logging
 
 import pycuda.compiler as cuda_compiler
 import pycuda.gpuarray
@@ -38,9 +39,9 @@ import pycuda.driver as cuda
 Class which keeps track of time spent for a section of code
 """
 class Timer(object):
-    def __init__(self, tag, verbose=True):
-        self.verbose = verbose
+    def __init__(self, tag):
         self.tag = tag
+        self.logger =  logging.getLogger(__name__)
         
     def __enter__(self):
         self.start = time.time()
@@ -50,8 +51,7 @@ class Timer(object):
         self.end = time.time()
         self.secs = self.end - self.start
         self.msecs = self.secs * 1000 # millisecs
-        if self.verbose:
-            print("=> " + self.tag + ' %f ms' % self.msecs)
+        self.logger.info("%s: %f ms", self.tag, self.msecs)
             
             
             
@@ -66,7 +66,8 @@ class CudaContext(object):
         self.verbose = verbose
         self.blocking = blocking
         self.use_cache = use_cache
-        self.modules = {}
+        self.logger =  logging.getLogger(__name__)
+        self.kernels = {}
         
         self.module_path = os.path.dirname(os.path.realpath(__file__))
         
@@ -74,63 +75,53 @@ class CudaContext(object):
         cuda.init(flags=0)
         
         #Print some info about CUDA
-        if (self.verbose):
-            print("CUDA version " + str(cuda.get_version()))
-            print("Driver version " + str(cuda.get_driver_version()))
+        self.logger.info("CUDA version %s", str(cuda.get_version()))
+        self.logger.info("Driver version %s",  str(cuda.get_driver_version()))
 
         self.cuda_device = cuda.Device(0)
         if (self.verbose):
-            print("Using " + self.cuda_device.name())
-            print(" => compute capability: " + str(self.cuda_device.compute_capability()))
-            print(" => memory: " + str(self.cuda_device.total_memory() / (1024*1024)) + " MB")
+            self.logger.info("Using '%s' GPU", self.cuda_device.name())
+            self.logger.debug(" => compute capability: %s", str(self.cuda_device.compute_capability()))
+            self.logger.debug(" => memory: %d MB", self.cuda_device.total_memory() / (1024*1024))
 
         # Create the CUDA context
         if (self.blocking):
             self.cuda_context = self.cuda_device.make_context(flags=cuda.ctx_flags.SCHED_BLOCKING_SYNC)
-            if (self.verbose):
-                print("=== WARNING ===")
-                print("Using blocking context")
-                print("=== WARNING ===")
+            self.logger.warning("Using blocking context")
         else:
             self.cuda_context = self.cuda_device.make_context(flags=cuda.ctx_flags.SCHED_AUTO)
         
-        if (self.verbose):
-            print("Created context <" + str(self.cuda_context.handle) + ">")
+        self.logger.info("Created context handle <%s>", str(self.cuda_context.handle))
         
         #Create cache dir for cubin files
         if (self.use_cache):
             self.cache_path = os.path.join(self.module_path, "cuda_cache") 
             if not os.path.isdir(self.cache_path):
                 os.mkdir(self.cache_path)
-            if (verbose):
-                print("Using CUDA cache dir " + self.cache_path)
+            self.logger.debug("Using CUDA cache dir %s", self.cache_path)
             
     
     def __del__(self, *args):
-        if self.verbose:
-            print("Cleaning up CUDA context <" + str(self.cuda_context.handle) + ">")
+        self.logger.info("Cleaning up CUDA context handle <%s>", str(self.cuda_context.handle))
             
         # Loop over all contexts in stack, and remove "this"
         other_contexts = []
         while (cuda.Context.get_current() != None):
             context = cuda.Context.get_current()
-            if (self.verbose):
-                if (context.handle != self.cuda_context.handle):
-                    print(" `-> <" + str(self.cuda_context.handle) + "> Popping context <" + str(context.handle) + "> which we do not own")
-                    other_contexts = [context] + other_contexts
-                    cuda.Context.pop()
-                else:
-                    print(" `-> <" + str(self.cuda_context.handle) + "> Popping context <" + str(context.handle) + "> (ourselves)")
-                    cuda.Context.pop()
+            if (context.handle != self.cuda_context.handle):
+                self.logger.debug("<%s> Popping <%s> (*not* ours)", str(self.cuda_context.handle), str(context.handle))
+                other_contexts = [context] + other_contexts
+                cuda.Context.pop()
+            else:
+                self.logger.debug("<%s> Popping <%s> (ours)", str(self.cuda_context.handle), str(context.handle))
+                cuda.Context.pop()
 
         # Add all the contexts we popped that were not our own
         for context in other_contexts:
-            if (self.verbose):
-                print(" `-> <" + str(self.cuda_context.handle) + "> Pushing <" + str(context.handle) + ">")
+            self.logger.debug("<%s> Pushing <%s>", str(self.cuda_context.handle), str(context.handle))
             cuda.Context.push(context)
             
-        if (self.verbose):
-            print(" `-> <" + str(self.cuda_context.handle) + "> Detaching context")
+        self.logger.debug("<%s> Detaching", str(self.cuda_context.handle))
         self.cuda_context.detach()
         
         
@@ -143,49 +134,45 @@ class CudaContext(object):
         num_includes = 0
         max_includes = 100
         kernel_hasher = hashlib.md5()
+        logger = logging.getLogger(__name__)
         
-        with Timer("compiler", verbose=False) as timer:
-            # Loop over file and includes, and check if something has changed
-            files = [kernel_filename]
-            while len(files):
+        # Loop over file and includes, and check if something has changed
+        files = [kernel_filename]
+        while len(files):
+        
+            if (num_includes > max_includes):
+                raise("Maximum number of includes reached - circular include in {:}?".format(kernel_filename))
+        
+            filename = files.pop()
             
-                if (num_includes > max_includes):
-                    raise("Maximum number of includes reached - circular include in {:}?".format(kernel_filename))
+            logger.debug("Hashing %s", filename)
+                
+            modified = os.path.getmtime(filename)
+                
+            # Open the file
+            with io.open(filename, "r") as file:
             
-                filename = files.pop()
+                # Search for #inclue <something> and also hash the file
+                file_str = file.read()
+                kernel_hasher.update(file_str.encode('utf-8'))
+                kernel_hasher.update(str(modified).encode('utf-8'))
                 
-                if (verbose):
-                    print("`-> Hashing " + filename)
-                    
-                modified = os.path.getmtime(filename)
-                    
-                # Open the file
-                with io.open(filename, "r") as file:
+                #Find all includes
+                includes = re.findall('^\W*#include\W+(.+?)\W*$', file_str, re.M)
                 
-                    # Search for #inclue <something> and also hash the file
-                    file_str = file.read()
-                    kernel_hasher.update(file_str.encode('utf-8'))
-                    kernel_hasher.update(str(modified).encode('utf-8'))
-                    
-                    #Find all includes
-                    includes = re.findall('^\W*#include\W+(.+?)\W*$', file_str, re.M)
-                    
-                # Loop over everything that looks like an include
-                for include_file in includes:
-                    
-                    #Search through include directories for the file
-                    file_path = os.path.dirname(filename)
-                    for include_path in [file_path] + include_dirs:
-                    
-                        # If we find it, add it to list of files to check
-                        temp_path = os.path.join(include_path, include_file)
-                        if (os.path.isfile(temp_path)):
-                            files = files + [temp_path]
-                            num_includes = num_includes + 1 #For circular includes...
-                            break
+            # Loop over everything that looks like an include
+            for include_file in includes:
                 
-        if (verbose):
-            print("`-> Hashed in " + str(timer.secs) + " seconds")
+                #Search through include directories for the file
+                file_path = os.path.dirname(filename)
+                for include_path in [file_path] + include_dirs:
+                
+                    # If we find it, add it to list of files to check
+                    temp_path = os.path.join(include_path, include_file)
+                    if (os.path.isfile(temp_path)):
+                        files = files + [temp_path]
+                        num_includes = num_includes + 1 #For circular includes...
+                        break
             
         return kernel_hasher.hexdigest()
     
@@ -200,82 +187,80 @@ class CudaContext(object):
         Helper function to print compilation output
         """
         def cuda_compile_message_handler(compile_success_bool, info_str, error_str):
-            if (verbose):
-                print("`-> Compilation returned " + str(compile_success_bool))
-                if info_str:
-                    print("`-> Info: " + info_str) 
-                if error_str:
-                    print("`-> Error: " + error_str) 
+            self.logger.debug("Compilation returned %s", str(compile_success_bool))
+            if info_str:
+                self.logger.debug("Info: %s", info_str)
+            if error_str:
+                self.logger.debug("Error: %s", error_str)
         
-        if (verbose):
-            print("Getting " + kernel_filename)
+        self.logger.debug("Getting %s", kernel_filename)
             
         # Create a hash of the kernel (and its includes)
+        kwargs_hasher = hashlib.md5()
+        kwargs_hasher.update(str(kwargs).encode('utf-8'));
+        kwargs_hash = kwargs_hasher.hexdigest()
+        kwargs_hasher = None
         root, ext = os.path.splitext(kernel_filename)
         kernel_hash = root \
                 + "_" + CudaContext.hash_kernel( \
                     os.path.join(self.module_path, kernel_filename), \
                     include_dirs=[self.module_path] + include_dirs, \
                     verbose=verbose) \
-                + "_" + str(hash(str(kwargs))) \
+                + "_" + kwargs_hash \
                 + ext
         cached_kernel_filename = os.path.join(self.cache_path, kernel_hash)
         
         # If we have the kernel in our hashmap, return it
-        if (kernel_hash in self.modules.keys()):
-            if (verbose):
-                print("`-> Found kernel " + kernel_hash + " cached in hashmap")
-            return self.modules[kernel_hash].get_function(kernel_function_name)
+        if (kernel_hash in self.kernels.keys()):
+            self.logger.debug("Found kernel %s cached in hashmap (%s)", kernel_filename, kernel_hash)
+            return self.kernels[kernel_hash]
         
         # If we have it on disk, return it
         elif (self.use_cache and os.path.isfile(cached_kernel_filename)):
-            if (verbose):
-                print("`-> Found kernel " + kernel_hash + " cached on disk")
+            self.logger.debug("Found kernel %s cached on disk (%s)", kernel_filename, kernel_hash)
                 
             with io.open(cached_kernel_filename, "rb") as file:
                 file_str = file.read()
                 module = cuda.module_from_buffer(file_str, message_handler=cuda_compile_message_handler)
                 
-            self.modules[kernel_hash] = module
-            kernel = self.modules[kernel_hash].get_function(kernel_function_name)
+            kernel = module.get_function(kernel_function_name)
             kernel.prepare(prepared_call_args)
+            self.kernels[kernel_hash] = kernel
             return kernel
             
         # Otherwise, compile it from source
         else:
-            if (verbose):
-                print("`-> Compiling " + kernel_filename)
+            self.logger.debug("Compiling %s (%s)", kernel_filename, kernel_hash)
                 
             #Create kernel string
             kernel_string = ""
             for key, value in kwargs.items():
                 kernel_string += "#define {:s} {:s}\n".format(str(key), str(value))
-            kernel_string += '#include "' + os.path.join(self.module_path, kernel_filename) + '"'
+            kernel_string += '#include "{:s}"'.format(os.path.join(self.module_path, kernel_filename))
             if (self.use_cache):
                 with io.open(cached_kernel_filename + ".txt", "w") as file:
                     file.write(kernel_string)
                 
             
-            with Timer("compiler", verbose=False) as timer:
+            with Timer("compiler") as timer:
                 cubin = cuda_compiler.compile(kernel_string, include_dirs=include_dirs, no_extern_c=no_extern_c, cache_dir=False)
                 module = cuda.module_from_buffer(cubin, message_handler=cuda_compile_message_handler)
-                self.modules[kernel_hash] = module
                 if (self.use_cache):
                     with io.open(cached_kernel_filename, "wb") as file:
                         file.write(cubin)
                 
-            if (verbose):
-                print("`-> Compiled in " + str(timer.secs) + " seconds")
-            
-            kernel = self.modules[kernel_hash].get_function(kernel_function_name)
+            kernel = module.get_function(kernel_function_name)
             kernel.prepare(prepared_call_args)
+            self.kernels[kernel_hash] = kernel
+            
+            
             return kernel
     
     """
     Clears the kernel cache (useful for debugging & development)
     """
     def clear_kernel_cache(self):
-        self.modules = {}
+        self.kernels = {}
         
         
         

SWESimulators/IPythonMagic.py

@@ -19,6 +19,8 @@ You should have received a copy of the GNU General Public License
 along with this program.  If not, see <http://www.gnu.org/licenses/>.
 """
 
+import logging
+
 from IPython.core.magic import line_magic, Magics, magics_class
 import pycuda.driver as cuda
 
@@ -28,29 +30,31 @@ import pycuda.driver as cuda
 class CudaContextHandler(Magics): 
     @line_magic
     def cuda_context_handler(self, context_name):
-        print("Registering " + context_name + " as a global context")
+        self.logger =  logging.getLogger(__name__)
+        
+        self.logger.debug("Registering %s as a global context", context_name)
         
         if context_name in self.shell.user_ns.keys():
-            print("`-> Context already registered! Ignoring")
+            self.logger.debug("Context already registered! Ignoring")
             return
         else:
-            print("`-> Creating context")
+            self.logger.debug("Creating context")
             self.shell.ex(context_name + " = Common.CudaContext(verbose=True, blocking=False)")
         
         # this function will be called on exceptions in any cell
         def custom_exc(shell, etype, evalue, tb, tb_offset=None):
-            print("Exception caught: Resetting to CUDA context " + context_name)
+            self.logger.exception("Exception caught: Resetting to CUDA context %s", context_name)
             while (cuda.Context.get_current() != None):
                 context = cuda.Context.get_current()
-                print("`-> popping " + str(context.handle))
+                self.logger.info("Popping <%s>", str(context.handle))
                 cuda.Context.pop()
 
             if context_name in self.shell.user_ns.keys():
-                print("`-> pushing " + str(self.shell.user_ns[context_name].cuda_context.handle))
+                self.logger.info("Pushing <%s>", str(self.shell.user_ns[context_name].cuda_context.handle))
                 self.shell.ex(context_name + ".cuda_context.push()")
             else:
-                print("No CUDA context called " + context_name + " found (something is wrong)!")
-                print("CUDA will not work now")
+                self.logger.error("No CUDA context called %s found (something is wrong)", context_name)
+                self.logger.error("CUDA will not work now")
 
             # still show the error within the notebook, don't just swallow it
             shell.showtraceback((etype, evalue, tb), tb_offset=tb_offset)
@@ -62,14 +66,15 @@ class CudaContextHandler(Magics):
         # Handle CUDA context when exiting python
         import atexit
         def exitfunc():
-            print("Exitfunc: Resetting CUDA context stack")
+            self.logger.info("Exitfunc: Resetting CUDA context stack")
             while (cuda.Context.get_current() != None):
                 context = cuda.Context.get_current()
-                print("`-> popping " + str(context.handle))
+                self.logger.info("`-> Popping <%s>", str(context.handle))
                 cuda.Context.pop()
         atexit.register(exitfunc)
 
-print("Registering automatic CUDA context handling")
-print("(use %cuda_context_handler my_context to create a context called my_context")
+logger = logging.getLogger(__name__)
+logger.info("Registering automatic CUDA context handling")
+logger.debug("(use %cuda_context_handler my_context to create a context called my_context")
 ip = get_ipython()
 ip.register_magics(CudaContextHandler)

SWESimulators/PlotHelper.py

@@ -1,165 +0,0 @@
-# -*- coding: utf-8 -*-
-
-"""
-This python class aids in plotting results from the numerical 
-simulations
-
-Copyright (C) 2016  SINTEF ICT
-
-This program is free software: you can redistribute it and/or modify
-it under the terms of the GNU General Public License as published by
-the Free Software Foundation, either version 3 of the License, or
-(at your option) any later version.
-
-This program is distributed in the hope that it will be useful,
-but WITHOUT ANY WARRANTY; without even the implied warranty of
-MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
-GNU General Public License for more details.
-
-You should have received a copy of the GNU General Public License
-along with this program.  If not, see <http://www.gnu.org/licenses/>.
-"""
-
-
-from matplotlib import pyplot as plt
-import matplotlib.gridspec as gridspec
-import numpy as np
-import time
-
-"""
-Class that makes plotting faster by caching the plots instead of recreating them
-"""
-class PlotHelper:
-
-    def __init__(self, fig, x_coords, y_coords, radius, eta1, u1, v1, eta2=None, u2=None, v2=None, interpolation_type='spline36'):
-        self.ny, self.nx = eta1.shape
-        self.fig = fig;
-        
-        fig.set_figheight(15)
-        fig.set_figwidth(15)
-        
-        min_x = np.min(x_coords[:,0]);
-        min_y = np.min(y_coords[0,:]);
-        
-        max_x = np.max(x_coords[0,:]);
-        max_y = np.max(y_coords[:,0]);
-        
-        domain_extent = [ x_coords[0, 0], x_coords[0, -1], y_coords[0, 0], y_coords[-1, 0] ]
-        
-        if (eta2 is not None):
-            assert(u2 is not None)
-            assert(v2 is not None)
-            self.gs = gridspec.GridSpec(3, 3)
-        else:
-            self.gs = gridspec.GridSpec(2, 3)
-        
-        ax = self.fig.add_subplot(self.gs[0, 0])
-        self.sp_eta = plt.imshow(eta1, interpolation=interpolation_type, origin='bottom', vmin=-0.05, vmax=0.05, extent=domain_extent)
-        plt.axis('tight')
-        ax.set_aspect('equal')
-        plt.title('Eta')
-        plt.colorbar()
-        
-        ax = self.fig.add_subplot(self.gs[0, 1])
-        self.sp_u = plt.imshow(u1, interpolation=interpolation_type, origin='bottom', vmin=-1.5, vmax=1.5, extent=domain_extent)
-        plt.axis('tight')
-        ax.set_aspect('equal')
-        plt.title('U')
-        plt.colorbar()
-        
-        ax = self.fig.add_subplot(self.gs[0, 2])
-        self.sp_v = plt.imshow(v1, interpolation=interpolation_type, origin='bottom', vmin=-1.5, vmax=1.5, extent=domain_extent)
-        plt.axis('tight')
-        ax.set_aspect('equal')
-        plt.title('V')
-        plt.colorbar()
-            
-        ax = self.fig.add_subplot(self.gs[1, 0])
-        self.sp_radial1, = plt.plot(radius.ravel(), eta1.ravel(), '.')
-        plt.axis([0, min(max_x, max_y), -1.5, 1])
-        plt.title('Eta Radial plot')
-
-        ax = self.fig.add_subplot(self.gs[1, 1])
-        self.sp_x_axis1, = plt.plot(x_coords[self.ny/2,:], eta1[self.ny/2,:], 'k+--', label='x-axis')
-        self.sp_y_axis1, = plt.plot(y_coords[:,self.nx/2], eta1[:,self.nx/2], 'kx:', label='y-axis')
-        plt.axis([max(min_x, min_y), min(max_x, max_y), -1.5, 1])
-        plt.title('Eta along axis')
-        plt.legend()
-
-        ax = self.fig.add_subplot(self.gs[1, 2])
-        self.sp_x_diag1, = plt.plot(1.41*np.diagonal(x_coords, offset=-abs(self.nx-self.ny)/2), \
-                                   np.diagonal(eta1, offset=-abs(self.nx-self.ny)/2), \
-                                   'k+--', label='x = -y')
-        self.sp_y_diag1, = plt.plot(1.41*np.diagonal(y_coords.T, offset=abs(self.nx-self.ny)/2), \
-                                   np.diagonal(eta1.T, offset=abs(self.nx-self.ny)/2), \
-                                   'kx:', label='x = y')
-        plt.axis([max(min_x, min_y), min(max_x, max_y), -1.5, 1])
-        plt.title('Eta along diagonal')
-        plt.legend()
-        
-        
-        if (eta2 is not None):
-            ax = self.fig.add_subplot(self.gs[2, 0])
-            self.sp_radial2, = plt.plot(radius.ravel(), eta2.ravel(), '.')
-            plt.axis([0, min(max_x, max_y), -1.5, 1])
-            plt.title('Eta2 Radial plot')
-
-            ax = self.fig.add_subplot(self.gs[2, 1])
-            self.sp_x_axis2, = plt.plot(x_coords[self.ny/2,:], eta2[self.ny/2,:], 'k+--', label='x-axis')
-            self.sp_y_axis2, = plt.plot(y_coords[:,self.nx/2], eta2[:,self.nx/2], 'kx:', label='y-axis')
-            plt.axis([max(min_x, min_y), min(max_x, max_y), -1.5, 1])
-            plt.title('Eta2 along axis')
-            plt.legend()
-
-            ax = self.fig.add_subplot(self.gs[2, 2])
-            self.sp_x_diag2, = plt.plot(1.41*np.diagonal(x_coords, offset=-abs(self.nx-self.ny)/2), \
-                                       np.diagonal(eta2, offset=-abs(self.nx-self.ny)/2), \
-                                       'k+--', label='x = -y')
-            self.sp_y_diag2, = plt.plot(1.41*np.diagonal(y_coords.T, offset=abs(self.nx-self.ny)/2), \
-                                       np.diagonal(eta2.T, offset=abs(self.nx-self.ny)/2), \
-                                       'kx:', label='x = y')
-            plt.axis([max(min_x, min_y), min(max_x, max_y), -1.5, 1])
-            plt.title('Eta2 along diagonal')
-            plt.legend()
-        
-        
-        
-        
-        
-    def plot(self, eta1, u1, v1, eta2=None, u2=None, v2=None):
-        self.fig.add_subplot(self.gs[0, 0])
-        self.sp_eta.set_data(eta1)
-
-        self.fig.add_subplot(self.gs[0, 1])
-        self.sp_u.set_data(u1)
-
-        self.fig.add_subplot(self.gs[0, 2])
-        self.sp_v.set_data(v1)
-            
-        self.fig.add_subplot(self.gs[1, 0])
-        self.sp_radial1.set_ydata(eta1.ravel());
-
-        self.fig.add_subplot(self.gs[1, 1])
-        self.sp_x_axis1.set_ydata(eta1[(self.ny+2)/2,:])
-        self.sp_y_axis1.set_ydata(eta1[:,(self.nx+2)/2])
-
-        self.fig.add_subplot(self.gs[1, 2])
-        self.sp_x_diag1.set_ydata(np.diagonal(eta1, offset=-abs(self.nx-self.ny)/2))
-        self.sp_y_diag1.set_ydata(np.diagonal(eta1.T, offset=abs(self.nx-self.ny)/2))
-        
-        if (eta2 is not None):
-            self.fig.add_subplot(self.gs[2, 0])
-            self.sp_radial2.set_ydata(eta2.ravel());
-
-            self.fig.add_subplot(self.gs[2, 1])
-            self.sp_x_axis2.set_ydata(eta2[(self.ny+2)/2,:])
-            self.sp_y_axis2.set_ydata(eta2[:,(self.nx+2)/2])
-
-            self.fig.add_subplot(self.gs[2, 2])
-            self.sp_x_diag2.set_ydata(np.diagonal(eta2, offset=-abs(self.nx-self.ny)/2))
-            self.sp_y_diag2.set_ydata(np.diagonal(eta2.T, offset=abs(self.nx-self.ny)/2))
-        
-        plt.draw()
-        time.sleep(0.001)
-        
-