Merge branch 'problame/zfs-command-logging-and-status' into problame/holds-release-and-hold-leak-fix-v2

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",
+    "import re\n"
-    "\n",
-    "%matplotlib notebook"
    ]
   },
   {
@@ -42,6 +40,9 @@
     "    dataset = None\n",
     "    if binary == \"zfs\":\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",
@@ -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": {

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 dateRegex = regexp.MustCompile(`^([^\[]+)(.*)`)
-var dateFormat string
+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()
 
+	if dateRegexArg != "" {
 		dateRegex = regexp.MustCompile(dateRegexArg)
+	}
 
 	input := bufio.NewScanner(os.Stdin)
 	input.Split(bufio.ScanLines)

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 == "") {