diff --git a/zfs/zfscmd/zfscmd-logging-scraper/analysis.ipynb b/zfs/zfscmd/zfscmd-logging-scraper/analysis.ipynb index 2a1ee72..fb1236b 100644 --- a/zfs/zfscmd/zfscmd-logging-scraper/analysis.ipynb +++ b/zfs/zfscmd/zfscmd-logging-scraper/analysis.ipynb @@ -9,9 +9,7 @@ "import pandas as pd\n", "import seaborn as sns\n", "import matplotlib.pyplot as plt\n", - "import re\n", - "\n", - "%matplotlib notebook" + "import re\n" ] }, { @@ -41,10 +39,13 @@ " \n", " dataset = None\n", " if binary == \"zfs\":\n", - " if verb == \"send\": \n", - " dataset = parse_ds(tail[-1])\n", - " if \"-n\" in tail:\n", - " verb = \"send-dry\"\n", + " if verb == \"send\": \n", + " if len(tail) == 0:\n", + " verb = \"send-feature-test\"\n", + " else:\n", + " dataset = parse_ds(tail[-1])\n", + " if \"-n\" in tail:\n", + " verb = \"send-dry\"\n", " elif verb == \"recv\" or verb == \"receive\":\n", " verb = \"receive\"\n", " if len(tail) > 0:\n", @@ -88,7 +89,9 @@ "res = df.apply(parse_cmd, axis='columns', result_type='expand')\n", "res = pd.concat([df, res], axis='columns')\n", "for cat in [\"action\", \"dataset\"]:\n", - " res[cat] = res[cat].astype('category')\n" + " res[cat] = res[cat].astype('category')\n", + "\n", + "res[\"LogTimeUnix\"] = pd.to_datetime(res.LogTime)" ] }, { @@ -154,6 +157,83 @@ "most_expensive_action_by_dataset.plot.barh(rot=50, fontsize=5, figsize=(10, 20))\n", "plt.savefig('most-expensive-command.pdf')" ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "res" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "# %matplotlib notebook \n", + "\n", + "# res.index = res.LogTimeUnix\n", + "\n", + "# resampled = res.pivot(columns='action', values='TotalTime').resample(\"1s\").sum()\n", + "# resampled.cumsum().plot()\n", + "# res[\"BeginTime\"] = res.LogTimeUnix.dt.total_seconds()\n", + "# holds = res[res.action == \"zfs-holds\"]\n", + "# sns.stripplot(x=\"LogTimeUnix\", y=\"action\", data=res)\n", + "# res[\"LogTimeUnix\"].resample(\"20min\").sum()\n", + "# res[res.action == \"zfs-holds\"].plot.scatter(x=\"LogTimeUnix\", y=\"TotalTime\")\n", + "\n", + "#res[res.action == \"zfs-holds\"].pivot(columns='action', values=['TotalTime', 'Systime', \"Usertime\"]).resample(\"1s\").sum().cumsum().plot()\n", + "pivoted = res.reset_index(drop=True).pivot_table(values=['TotalTime', 'Systime', \"Usertime\"], index=\"LogTimeUnix\", columns=\"action\")\n", + "pivoted" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "pivoted.cumsum()[[(\"TotalTime\", \"zfs-holds\"),(\"Systime\", \"zfs-holds\"),(\"Usertime\", \"zfs-holds\")]].plot()" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "pivoted = res.reset_index(drop=True).pivot_table(values=['TotalTime'], index=\"LogTimeUnix\", columns=\"action\")\n", + "cum_invocation_counts_per_action = pivoted.isna().astype(int).cumsum()" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "cum_invocation_counts_per_action" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "# zfs-get as reference value\n", + "cum_invocation_counts_per_action[[(\"TotalTime\",\"zfs-holds\"),(\"TotalTime\",\"zfs-get\")]].plot()" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [] } ], "metadata": { diff --git a/zfs/zfscmd/zfscmd-logging-scraper/zfscmd_logging_scraper.go b/zfs/zfscmd/zfscmd-logging-scraper/zfscmd_logging_scraper.go index d7670cf..6d33f08 100644 --- a/zfs/zfscmd/zfscmd-logging-scraper/zfscmd_logging_scraper.go +++ b/zfs/zfscmd/zfscmd-logging-scraper/zfscmd_logging_scraper.go @@ -12,6 +12,7 @@ import ( "github.com/go-logfmt/logfmt" "github.com/pkg/errors" "github.com/spf13/pflag" + "github.com/zrepl/zrepl/daemon/logging" ) @@ -75,9 +76,10 @@ func parseLogLine(line string) (l RuntimeLine, err error) { if len(m) != 3 { return l, errors.Errorf("invalid date regex match %v", m) } - date, err := time.Parse(dateFormat, strings.TrimSpace(m[1])) + dateTrimmed := strings.TrimSpace(m[1]) + date, err := time.Parse(dateFormat, dateTrimmed) if err != nil { - panic(fmt.Sprintf("cannot parse date %q: %s", m[1], err)) + panic(fmt.Sprintf("cannot parse date %q: %s", dateTrimmed, err)) } logLine := m[2] @@ -88,17 +90,19 @@ func parseLogLine(line string) (l RuntimeLine, err error) { var verbose bool var dateRegexArg string -var dateRegex *regexp.Regexp -var dateFormat string +var dateRegex = regexp.MustCompile(`^([^\[]+)(.*)`) +var dateFormat = logging.HumanFormatterDateFormat func main() { - pflag.StringVarP(&dateRegexArg, "dateRE", "d", `^([^\[]+)(.*)`, "date regex") + pflag.StringVarP(&dateRegexArg, "dateRE", "d", "", "date regex") pflag.StringVar(&dateFormat, "dateFormat", logging.HumanFormatterDateFormat, "go date format") pflag.BoolVarP(&verbose, "verbose", "v", false, "verbose") pflag.Parse() - dateRegex = regexp.MustCompile(dateRegexArg) + if dateRegexArg != "" { + dateRegex = regexp.MustCompile(dateRegexArg) + } input := bufio.NewScanner(os.Stdin) input.Split(bufio.ScanLines) diff --git a/zfs/zfscmd/zfscmd-logging-scraper/zfscmd_logging_scrapter_test.go b/zfs/zfscmd/zfscmd-logging-scraper/zfscmd_logging_scrapter_test.go index de137d1..2bea1f2 100644 --- a/zfs/zfscmd/zfscmd-logging-scraper/zfscmd_logging_scrapter_test.go +++ b/zfs/zfscmd/zfscmd-logging-scraper/zfscmd_logging_scrapter_test.go @@ -5,9 +5,11 @@ import ( "time" "github.com/stretchr/testify/require" + + "github.com/zrepl/zrepl/daemon/logging" ) -func TestParseHumanFormatterNodate(t *testing.T) { +func TestParseHumanFormatter(t *testing.T) { type testCase struct { Name string @@ -22,45 +24,51 @@ func TestParseHumanFormatterNodate(t *testing.T) { return d } + logTime, err := time.Parse(logging.HumanFormatterDateFormat, "2020-04-04T00:00:05+02:00") + require.NoError(t, err) + tcs := []testCase{ { Name: "human-formatter-noerror", - Input: `[jobname][zfs.cmd]: command exited without error usertime_s="0.008445" cmd="zfs list -H -p -o name -r -t filesystem,volume" systemtime_s="0.033783" invocation="84" total_time_s="0.037828619"`, + Input: `2020-04-04T00:00:05+02:00 [DEBG][jobname][zfs.cmd]: command exited without error usertime_s="0.008445" cmd="zfs list -H -p -o name -r -t filesystem,volume" systemtime_s="0.033783" invocation="84" total_time_s="0.037828619"`, Expect: &RuntimeLine{ Cmd: "zfs list -H -p -o name -r -t filesystem,volume", TotalTime: secs("0.037828619"), Usertime: secs("0.008445"), Systime: secs("0.033783"), Error: "", + LogTime: logTime, }, }, { Name: "human-formatter-witherror", - Input: `[jobname][zfs.cmd]: command exited with error usertime_s="0.008445" cmd="zfs list -H -p -o name -r -t filesystem,volume" systemtime_s="0.033783" invocation="84" total_time_s="0.037828619" err="some error"`, + Input: `2020-04-04T00:00:05+02:00 [DEBG][jobname][zfs.cmd]: command exited with error usertime_s="0.008445" cmd="zfs list -H -p -o name -r -t filesystem,volume" systemtime_s="0.033783" invocation="84" total_time_s="0.037828619" err="some error"`, Expect: &RuntimeLine{ Cmd: "zfs list -H -p -o name -r -t filesystem,volume", TotalTime: secs("0.037828619"), Usertime: secs("0.008445"), Systime: secs("0.033783"), Error: "some error", + LogTime: logTime, }, }, { Name: "from graylog", - Input: `[csnas][zfs.cmd]: command exited without error usertime_s="0" cmd="zfs send -i zroot/ezjail/synapse-12@zrepl_20200329_095518_000 zroot/ezjail/synapse-12@zrepl_20200329_102454_000" total_time_s="0.101598591" invocation="85" systemtime_s="0.041581"`, + Input: `2020-04-04T00:00:05+02:00 [DEBG][csnas][zfs.cmd]: command exited without error usertime_s="0" cmd="zfs send -i zroot/ezjail/synapse-12@zrepl_20200329_095518_000 zroot/ezjail/synapse-12@zrepl_20200329_102454_000" total_time_s="0.101598591" invocation="85" systemtime_s="0.041581"`, Expect: &RuntimeLine{ Cmd: "zfs send -i zroot/ezjail/synapse-12@zrepl_20200329_095518_000 zroot/ezjail/synapse-12@zrepl_20200329_102454_000", TotalTime: secs("0.101598591"), Systime: secs("0.041581"), Usertime: secs("0"), Error: "", + LogTime: logTime, }, }, } for _, c := range tcs { t.Run(c.Name, func(t *testing.T) { - l, err := parseHumanFormatterNodate(c.Input) + l, err := parseLogLine(c.Input) t.Logf("l=%v", l) t.Logf("err=%T %v", err, err) if (c.Expect != nil && c.ExpectErr != "") || (c.Expect == nil && c.ExpectErr == "") {