Zenn
🔥

PythonのLoggerをStackdriverに流して情報を可視化する

2020/11/12に公開
GCP
Python
機械学習
#
log
Stackdriver
tech

はじめに

white, inc の ソフトウェアエンジニア r2en です。
自社では新規事業を中心としたコンサルタント業務を行なっており、
普段エンジニアは、新規事業を開発する無料のクラウド型ツール を開発したり、
新規事業のコンサルティングからPoC開発まで携わります

image

今回は、機械学習の技術調査を行なったので記事で共有させていただきます
以下から文章が長くなりますので、口語で記述させていただきます

問題

  • 複数のリモートインスタンス上でサーバを走らせる場合、実行結果をどこで集約して監視するか考えることが多くなったので、PythonのLoggerを通してStackdriverに情報を流したいと考えた
  • 機械学習系のデバッグあるあるかもしれないが、頻繁に関数の実行時間と返り値の型や形状、変数の型や形状を確認することが頻発したため、勝手にデータ型に応じて出力する情報を分けてくれると嬉しいと考えた

環境

macOS Mojava ver 10.14.6
pyenv, pipenv, python ver. 3.6.8

ローカル設定

忘れてしまって申し訳ないんですが、多分、gcloudの設定をPCにしておく必要性があった気がする...

$ curl https://sdk.cloud.google.com | bash
$ pipenv install gcloud

今回使うライブラリをインストール

$ pipenv install google-cloud-logging

GCP設定

サービスアカウントの設定

IAMと管理のサービスアカウントから、サービスアカウントを作成する

スクリーンショット 2019-10-26 12 39 27

クレデンシャル情報の取得

Cloud APIを使用する(ローカルからGCPを操作する)場合、サービスを使うための認証情報が必要になるので取得する

Google Cloud Document 認証

image

  1. ServiceAccountを入力し、keyタイプをJSONに選択する。
  2. Createボタンを押すとダウンロード画面に行くため、下記フォルダ構成のようにjsonファイルを配置する

Create Service account key

スクリーンショット 2019-10-26 12 28 07

フォルダ構成

├── main.py                          <- 実行するファイル
├── utils
    ├── operation_stackdriver.py     <- Stack Driver Logging 操作に関するクラス
    └── credential-344323q5e32.json  <- クレデンシャル情報

ソースコード

operation_stackdriver.py
import os
import uuid
import time
import numpy
import pandas
import logging
import functools
from pathlib import Path
import google.cloud.logging
from datetime import datetime
from typing import List, Set, Dict, Tuple, TypeVar, Callable
from logging import getLogger, Formatter, FileHandler, StreamHandler, INFO, DEBUG


VERSION = datetime.now().strftime("%Y%m%d%H%M") + '_' + str(uuid.uuid4())


def _inspect_data(logger, name:str, data, time:float=None) -> None:
    '''
    loggerに各データの情報を記載する
    '''
    if isinstance(data, pandas.DataFrame):
        logger(f'{name}', {
            'hader': f'{data.head(3)}',
            'describe': f'{data.describe()}',
            'type': f'{type(data)}',
            'shape': f'{data.shape}',
            'dtypes': f'{data.dtypes}',
            'time': f'done in {time}'
        })
    elif isinstance(data, pandas.Series):
        logger(f'{name}', {
            'describe': f'{data.describe()}',
            'type': f'{type(data)}',
            'shape': f'{data.shape}',
            'dtypes': f'{data.dtypes}',
            'time': f'done in {time}'
        })
    elif isinstance(data, numpy.ndarray):
        logger(f'{name}', {
            'type': f'{type(data)}',
            'shape': f'{data.shape}',
            'time': f'done in {time}'
        })
    elif isinstance(data, str):
        logger(f'{name}', {
            'data': f'{data}',
            'type': f'{type(data)}',
            'time': f'done in {time}'
        })
    elif isinstance(data, int):
        logger(f'{name}', {
            'data': f'{data}',
            'type': f'{type(data)}',
            'time': f'done in {time}'
        })
    elif isinstance(data, float):
        logger(f'{name}', {
            'data': f'{data}',
            'type': f'{type(data)}',
            'time': f'done in {time}'
        })
    elif isinstance(data, bool):
        logger(f'{name}', {
            'data': f'{data}',
            'type': f'{type(data)}',
            'time': f'done in {time}'
        })
    elif isinstance(data, dict):
        logger(f'{name}', {
            'data': f'{data}',
            'type': f'{type(data)}',
            'shape': f'{len(data)}',
            'time': f'done in {time}'
        })
    elif isinstance(data, tuple):
        logger(f'{name}', {
            'data': f'{data}',
            'type': f'{type(data)}',
            'shape': f'{len(data)}',
            'time': f'done in {time}'
        })
    elif isinstance(data, list):
        logger(f'{name}', {
            'data': f'{data}',
            'type': f'{type(data)}',
            'shape': f'{len(data)}',
            'time': f'done in {time}'
        })
    else:
        logger(f'{name}', {
            'data': f'{data}',
            'time': f'done in {time}'
        })

def logger_function():
    '''
    デコレータで各関数の実行時間や返り値のデータ型などをloggerに記載する
    '''
    def _function_logger(function: Callable):
        @functools.wraps(function)
        def wrapper(*args, **kwargs):
            t0 = time.time()
            data = function(*args, **kwargs)
            _inspect_data(getLogger(VERSION).debug, f'function::{function.__name__}', data, time.time()-t0)
            return data
        return wrapper
    return _function_logger


class CustomFormatter(Formatter):
    '''
    メッセージと値のセットでloggerに記載するようにフォーマットを変更する 
    '''
    def format(self, record: logging.LogRecord):
        logmsg = super(CustomFormatter, self).format(record)
        return {'msg': logmsg, 'args':record.args}


def logger_create():
    '''
    Google Stack Driverにログを記載するようにloggerの初期設定を行う
    '''
    parameter = {}
    parameter["project_name"] = "project-291031"
    parameter["credential_path"] = "utils/credential-344323q5e32.json"
    os.environ["GOOGLE_APPLICATION_CREDENTIALS"] = str((Path(Path.cwd()).parent)/parameter["credential_path"])
    credentials = str((Path(Path.cwd()).parent)/parameter["credential_path"])
    client = google.cloud.logging.Client(parameter["project_name"]).from_service_account_json(credentials)

    client.setup_logging()
    cf = client.get_default_handler()
    cf.setFormatter(CustomFormatter())

    logger_ = getLogger(VERSION)
    logger_.setLevel(DEBUG)

    logger_.addHandler(cf)
    getLogger(VERSION).info(f'StackDriver Logging: {VERSION}', {'experiment number': f'{VERSION}'})


def logger_value(logger_type:str, data_name:str=None, data=None) -> None:
    '''
    変数の各データ情報をloggerに記載する
    '''
    if logger_type == 'info': _inspect_data(getLogger(VERSION).info, data_name, data)
    elif logger_type == 'debug': _inspect_data(getLogger(VERSION).debug, data_name, data)
    else: print(f'name::{data_name} value::{data} type::{type(data)}')
credential-344323q5e32.json
{
  "type": "service_account",
  "project_id": "project-291031",
  "private_key_id": "464564c7f86786afsa453345dsf234vr32",
  "private_key": "-----BEGIN PRIVATE KEY-----\ndD\n-----END PRIVATE KEY-----\n",
  "client_email": "my-email-address@project-291031.iam.gserviceaccount.com",
  "client_id": "543423423542344334",
  "auth_uri": "https://accounts.google.com/o/oauth2/auth",
  "token_uri": "https://oauth2.googleapis.com/token",
  "auth_provider_x509_cert_url": "https://www.googleapis.com/oauth2/v1/certs",
  "client_x509_cert_url": "https://www.googleapis.com/robot/v1/metadata/d453/my-email-address@project-291031.iam.gserviceaccount.com"
}

PythonのLoggerをStackdriverに流して情報を可視化する

  • logger_create()で、PythonのLoggerにstackdriverをオーバーラップさせて起動する
  • @logger_function()デコレータで、関数の終了時に、返り値のデータ型と、関数の実行時間を調べることができる
  • logger_value(logger_type, data_name, data)で、変数の各データ情報を調べることができる
main.py
from utils.operation_stackdriver import logger_create, logger_function, logger_value

import numpy
from sklearn.datasets import load_boston
from sklearn.model_selection import train_test_split
from typing import List, Set, Dict, Tuple, TypeVar, Callable

@logger_function()
def make_dataset() -> Tuple[numpy.ndarray, numpy.ndarray, numpy.ndarray, numpy.ndarray]:
    boston = load_boston()
    X, y = boston.data, boston.target
    X_train, X_valid, y_train, y_valid = train_test_split(X, y)
    return X_train, X_valid, y_train, y_valid
    
    
def main():
    logger_create()
    X_train, X_valid, y_train, y_valid = make_dataset()
    logger_value('info', 'X_train', X_train)

実行ログ

StackDriver Logging: 201910261643_c1763e9e-95c0-4243-98f6-e1750b47e67b
function::make_dataset
X_train

Google Cloud Platform の StackdriverのLoggingページを見る

プロジェクトのStackdriver Loggingを開いて、実行時に表示された実験番号(日付け＋uuid)で検索すると、1.logging初回起動、2.関数、3.変数 が表示されているのがわかる

スクリーンショット 2019-10-26 16 58 54

一つずつ開いてくと、

関数

こちらスクリーンショットに収まりきらないため省略するが、関数名と、関数の実行時間、返り値のデータの形状、返り値のデータ型などの情報が記載されている

スクリーンショット 2019-10-26 16 59 57

変数

変数名と、変数の形状、変数のデータ型などの情報が記載されている
スクリーンショット 2019-10-26 16 59 35

Discussion