github.com/chipaca/snappy@v0.0.0-20210104084008-1f06296fe8ad/osutil/strace/timing_test.go (about) 1 // -*- Mode: Go; indent-tabs-mode: t -*- 2 3 /* 4 * Copyright (C) 2018 Canonical Ltd 5 * 6 * This program is free software: you can redistribute it and/or modify 7 * it under the terms of the GNU General Public License version 3 as 8 * published by the Free Software Foundation. 9 * 10 * This program is distributed in the hope that it will be useful, 11 * but WITHOUT ANY WARRANTY; without even the implied warranty of 12 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 13 * GNU General Public License for more details. 14 * 15 * You should have received a copy of the GNU General Public License 16 * along with this program. If not, see <http://www.gnu.org/licenses/>. 17 * 18 */ 19 20 package strace_test 21 22 import ( 23 "bytes" 24 "io/ioutil" 25 "os" 26 27 . "gopkg.in/check.v1" 28 29 "github.com/snapcore/snapd/osutil/strace" 30 ) 31 32 type timingSuite struct{} 33 34 var _ = Suite(&timingSuite{}) 35 36 func (s *timingSuite) TestNewExecveTiming(c *C) { 37 et := strace.NewExecveTiming(10) 38 c.Assert(et, FitsTypeOf, &strace.ExecveTiming{}) 39 } 40 41 func (s *timingSuite) TestDisplayExeRuntimes(c *C) { 42 // setup mock traces 43 stt := strace.NewExecveTiming(3) 44 stt.TotalTime = 2.71828 45 stt.AddExeRuntime("slow", 1.0001) 46 stt.AddExeRuntime("fast", 0.1002) 47 stt.AddExeRuntime("really-fast", 0.0301) 48 stt.AddExeRuntime("medium", 0.5003) 49 50 // display works and shows the slowest 3 calls in order 51 buf := bytes.NewBuffer(nil) 52 stt.Display(buf) 53 c.Check(buf.String(), Equals, `Slowest 3 exec calls during snap run: 54 1.000s slow 55 0.100s fast 56 0.500s medium 57 Total time: 2.718s 58 `) 59 } 60 61 func (s *timingSuite) TestExecveTimingPrunes(c *C) { 62 stt := strace.NewExecveTiming(3) 63 64 // simple cases 65 stt.AddExeRuntime("t0", 2) 66 c.Check(stt.ExeRuntimes(), HasLen, 1) 67 stt.AddExeRuntime("t1", 1) 68 c.Check(stt.ExeRuntimes(), HasLen, 2) 69 stt.AddExeRuntime("t2", 5) 70 c.Check(stt.ExeRuntimes(), HasLen, 3) 71 72 // starts pruing the fastest call, keeps order otherwise 73 stt.AddExeRuntime("t3", 4) 74 c.Check(stt.ExeRuntimes(), HasLen, 3) 75 c.Check(stt.ExeRuntimes(), DeepEquals, []strace.ExeRuntime{ 76 {Exe: "t0", TotalSec: 2}, 77 {Exe: "t2", TotalSec: 5}, 78 {Exe: "t3", TotalSec: 4}, 79 }) 80 81 } 82 83 // generated with: 84 // sudo /usr/lib/snapd/snap-discard-ns test-snapd-tools && sudo strace -u $USER -o strace.log -f -e trace=execve,execveat -ttt test-snapd-tools.echo foo && cat strace.log 85 var sampleStraceSimple = []byte(`21616 1542882400.198907 execve("/snap/bin/test-snapd-tools.echo", ["test-snapd-tools.echo", "foo"], 0x7fff7f275f48 /* 27 vars */) = 0 86 21616 1542882400.204710 execve("/snap/core/current/usr/bin/snap", ["test-snapd-tools.echo", "foo"], 0xc42011c8c0 /* 27 vars */ <unfinished ...> 87 21621 1542882400.204845 +++ exited with 0 +++ 88 21620 1542882400.204853 +++ exited with 0 +++ 89 21619 1542882400.204857 +++ exited with 0 +++ 90 21618 1542882400.204861 +++ exited with 0 +++ 91 21617 1542882400.204875 +++ exited with 0 +++ 92 21616 1542882400.205199 <... execve resumed> ) = 0 93 21616 1542882400.220845 execve("/snap/core/5976/usr/lib/snapd/snap-confine", ["/snap/core/5976/usr/lib/snapd/sn"..., "snap.test-snapd-tools.echo", "/usr/lib/snapd/snap-exec", "test-snapd-tools.echo", "foo"], 0xc8200a3600 /* 41 vars */ <unfinished ...> 94 21625 1542882400.220994 +++ exited with 0 +++ 95 21624 1542882400.220999 +++ exited with 0 +++ 96 21623 1542882400.221002 +++ exited with 0 +++ 97 21622 1542882400.221005 +++ exited with 0 +++ 98 21616 1542882400.221634 <... execve resumed> ) = 0 99 21629 1542882400.356625 execveat(3, "", ["snap-update-ns", "--from-snap-confine", "test-snapd-tools"], 0x7ffeaf4faa40 /* 0 vars */, AT_EMPTY_PATH) = 0 100 21631 1542882400.360708 +++ exited with 0 +++ 101 21632 1542882400.360723 +++ exited with 0 +++ 102 21630 1542882400.360727 +++ exited with 0 +++ 103 21633 1542882400.360842 +++ exited with 0 +++ 104 21629 1542882400.360848 +++ exited with 0 +++ 105 21616 1542882400.360869 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=21629, si_uid=1000, si_status=0, si_utime=0, si_stime=0} --- 106 21626 1542882400.375793 +++ exited with 0 +++ 107 21616 1542882400.375836 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=21626, si_uid=1000, si_status=0, si_utime=0, si_stime=0} --- 108 21616 1542882400.377349 execve("/usr/lib/snapd/snap-exec", ["/usr/lib/snapd/snap-exec", "test-snapd-tools.echo", "foo"], 0x23ebc80 /* 45 vars */) = 0 109 21616 1542882400.383698 execve("/snap/test-snapd-tools/6/bin/echo", ["/snap/test-snapd-tools/6/bin/ech"..., "foo"], 0xc420072f00 /* 47 vars */ <unfinished ...> 110 21638 1542882400.383855 +++ exited with 0 +++ 111 21637 1542882400.383862 +++ exited with 0 +++ 112 21636 1542882400.383877 +++ exited with 0 +++ 113 21634 1542882400.383884 +++ exited with 0 +++ 114 21635 1542882400.383890 +++ exited with 0 +++ 115 21616 1542882400.384105 <... execve resumed> ) = 0 116 21616 1542882400.384974 +++ exited with 0 +++ 117 `) 118 119 func (s *timingSuite) TestTraceExecveTimings(c *C) { 120 f, err := ioutil.TempFile("", "strace-extract-test-") 121 c.Assert(err, IsNil) 122 defer os.Remove(f.Name()) 123 _, err = f.Write(sampleStraceSimple) 124 c.Assert(err, IsNil) 125 f.Sync() 126 127 st, err := strace.TraceExecveTimings(f.Name(), 10) 128 c.Assert(err, IsNil) 129 c.Assert(st.TotalTime, Equals, 0.1860671043395996) 130 c.Assert(st.ExeRuntimes(), DeepEquals, []strace.ExeRuntime{ 131 {Exe: "/snap/bin/test-snapd-tools.echo", TotalSec: 0.005803108215332031}, 132 {Exe: "/snap/core/current/usr/bin/snap", TotalSec: 0.016134977340698242}, 133 {Exe: "snap-update-ns", TotalSec: 0.0042438507080078125}, 134 {Exe: "/snap/core/5976/usr/lib/snapd/snap-confine", TotalSec: 0.15650391578674316}, 135 {Exe: "/usr/lib/snapd/snap-exec", TotalSec: 0.006349086761474609}, 136 }) 137 }