On Wed, Jan 3, 2018 at 4:03 PM, Waldek Kozaczuk <jwkozac...@gmail.com> wrote:
> I have played with the branch > https://github.com/benoit-canet/osv/tree/go4 and made some progress with > golang support. I have actually merged master into this branch and tried to > run the hello world against various golang versions. It worked with no > problems against 1.7.6 but not against 1.8.3 or latest 1.9.2. Luckily after > some research and putting number of debug statements into golang runtime > itself (more about this technique later) I found out that newer versions of > golang rely on the page size parameter to be passed in as AT_PAGESZ of auxv > array when initializing shared library. Thanks to all the ground work of > @benoit-canet it was actually very easy to add missing parameters and now > the hello world is working against 3 mentioned golang versions. > Excellent. It seems like the Go guys cannot miss any opportunity to use each and every crazy ABI feature in Linux :-) At some point we should try to start pushing Benoit's batches - and your new ones - into the main OSv. In the last round I had some review comments, I can't say I remember what they where :-) > Obviously it still "hangs at the end" (requires ctrl-C to exit) which > seems to be an issue @nyharel described as a thread not being terminated > and might require similar approach as java - special bootstrap gomain > program. > Yes, maybe https://github.com/cloudius-systems/osv/issues/850 > > On a side note newer version of go also use 270 and 267 syscall (1st is > pselect6 I think) which has libc implementation in OSv so adding syscall > support should not be difficult. The app obviously works without this calls. > > I have also played with more complicated httpserver example and managed to > reproduce some of the issues (I think) described in https://github.com/ > cloudius-systems/osv/issues/808. > > Here is the golang program I tried: > package main > > > import ( > "io" > "net/http" > "runtime" > "C" > ) > > > func hello(w http.ResponseWriter, r *http.Request) { > io.WriteString(w, "Hello world from " + runtime.Version()) > } > > > func main() { > } > > > //export GoMain > func GoMain() { > http.HandleFunc("/", hello) > http.ListenAndServe(":8000", nil) > } > > > To reproduce issue I used apache benchmarking tool (ab) to hit with enough > concurrency to trigger breakdown (c - is a concurrency limit): > > ab -c 100 -n 100 http://localhost:8000/ > > The app worked fined with concurrency limit up to 40-45 but definitely > would break with concurrency above 50 with all kind of stack traces. I am > putting some examples below: > > 1. > runtime.systemstack(0x20000065e558) > /home/wkozaczuk/tools/go-1.9.2/go/src/runtime/asm_amd64.s:360 +0xa1 > runtime.dopanic(0x0) > /home/wkozaczuk/tools/go-1.9.2/go/src/runtime/panic.go:586 +0x5a > runtime.throw(0x1000013270a5, 0x17) > /home/wkozaczuk/tools/go-1.9.2/go/src/runtime/panic.go:605 +0x97 > runtime.unlock(0x10000176c800) > /home/wkozaczuk/tools/go-1.9.2/go/src/runtime/lock_futex.go:109 +0xc6 > runtime.dopanic_m(0xc420001200, 0x10000113be67, 0x20000065e6a8) > /home/wkozaczuk/tools/go-1.9.2/go/src/runtime/panic.go:720 +0x23d > runtime.dopanic.func1() > /home/wkozaczuk/tools/go-1.9.2/go/src/runtime/panic.go:587 +0x3e > runtime.systemstack(0x20000065e678) > > 2. > #0 0x0000000000390d92 in processor::cli_hlt () at > arch/x64/processor.hh:247 > #1 arch::halt_no_interrupts () at arch/x64/arch.hh:48 > #2 osv::halt () at arch/x64/power.cc:24 > #3 0x0000000000225897 in abort (fmt=fmt@entry=0x719a00 "general > protection fault\n") at runtime.cc:132 > #4 0x000000000038bb5a in general_protection (ef=0xffff800002ad3068) at > arch/x64/exceptions.cc:322 > #5 <signal handler called> > #6 0x00001000012f8d6d in net/http.(*response).finishRequest (w= > 0x40314a <epoll_wake(epoll_ptr const&)+458>) > at /home/wkozaczuk/tools/go-1.9.2/go/src/net/http/server.go:1518 > #7 0x000000c420036da0 in ?? () > #8 0x000000000040314a in epoll_file::wake (key=..., this=0xc4200482c0) at > core/epoll.cc:231 > #9 epoll_wake (ep=...) at core/epoll.cc:347 > Backtrace stopped: previous frame identical to this frame (corrupt stack?) > > 3. > > wkozaczuk@wkoMacBookPro:~/projects/waldek-osv$ cat > golang-httpserver.failure3 > (gdb) bt > #0 0x0000000000390d92 in processor::cli_hlt () at > arch/x64/processor.hh:247 > #1 arch::halt_no_interrupts () at arch/x64/arch.hh:48 > #2 osv::halt () at arch/x64/power.cc:24 > #3 0x0000000000225897 in abort (fmt=fmt@entry=0x719a00 "general > protection fault\n") at runtime.cc:132 > #4 0x000000000038bb5a in general_protection (ef=0xffff800002ad3068) at > arch/x64/exceptions.cc:322 > #5 <signal handler called> > #6 0x00001000012f8d6d in net/http.(*response).finishRequest (w= > 0x40314a <epoll_wake(epoll_ptr const&)+458>) > at /home/wkozaczuk/tools/go-1.9.2/go/src/net/http/server.go:1518 > #7 0x000000c420036da0 in ?? () > #8 0x000000000040314a in epoll_file::wake (key=..., this=0xc4200482c0) at > core/epoll.cc:231 > #9 epoll_wake (ep=...) at core/epoll.cc:347 > Backtrace stopped: previous frame identical to this frame (corrupt stack?) > > wkozaczuk@wkoMacBookPro:~/projects/waldek-osv$ cat > golang-httpserver.failure4 > #0 0x0000000000390d92 in processor::cli_hlt () at > arch/x64/processor.hh:247 > #1 arch::halt_no_interrupts () at arch/x64/arch.hh:48 > #2 osv::halt () at arch/x64/power.cc:24 > #3 0x0000000000225897 in abort (fmt=fmt@entry=0x69d278 "Assertion > failed: %s (%s: %s: %d)\n") > at runtime.cc:132 > #4 0x00000000002258d9 in __assert_fail (expr=expr@entry=0x726a67 > "sched::preemptable()", > file=file@entry=0x71986a "arch/x64/mmu.cc", line=line@entry=33, > func=func@entry=0x719890 <page_fault::__func__> "page_fault") at > runtime.cc:139 > #5 0x000000000038a9e7 in page_fault (ef=0xffff800002996068) at > arch/x64/mmu.cc:33 > #6 <signal handler called> > #7 preempt_lock_t::unlock (this=<optimized out>) at > include/osv/preempt-lock.hh:16 > #8 std::lock_guard<preempt_lock_t>::~lock_guard (this=<synthetic > pointer>, __in_chrg=<optimized out>) > at /usr/include/c++/5/mutex:392 > #9 lock_guard_for_with_lock<preempt_lock_t>::~lock_guard_for_with_lock > (this=<synthetic pointer>, > __in_chrg=<optimized out>) at include/osv/mutex.h:74 > #10 memory::pool::alloc (this=0xc30580 <memory::malloc_pools+96>) at > core/mempool.cc:215 > #11 0x00000000003d37ac in std_malloc (size=size@entry=16, > alignment=alignment@entry=16) > at core/mempool.cc:1550 > #12 0x00000000003d3ad7 in malloc (size=16) at core/mempool.cc:1742 > #13 0x000000000048c568 in operator new(unsigned long) () > #14 0x000000000042aa51 in __gnu_cxx::new_allocator<iovec>::allocate > (this=<synthetic pointer>, __n=1) > at /usr/include/c++/5/ext/new_allocator.h:104 > #15 std::allocator_traits<std::allocator<iovec> >::allocate > (__a=<synthetic pointer>, __n=1) > at /usr/include/c++/5/bits/alloc_traits.h:491 > #16 std::_Vector_base<iovec, std::allocator<iovec> >::_M_allocate > (this=<synthetic pointer>, __n=1) > at /usr/include/c++/5/bits/stl_vector.h:170 > #17 std::vector<iovec, std::allocator<iovec> >::_M_range_initialize<iovec > const*> ( > __last=<optimized out>, __first=<optimized out>, this=<synthetic > pointer>) > at /usr/include/c++/5/bits/stl_vector.h:1287 > #18 std::vector<iovec, std::allocator<iovec> >::_M_initialize_dispatch<iovec > const*> ( > __last=<optimized out>, __first=<optimized out>, this=<synthetic > pointer>) > at /usr/include/c++/5/bits/stl_vector.h:1263 > #19 std::vector<iovec, std::allocator<iovec> >::vector<iovec const*, void> > (__a=..., > __last=<optimized out>, __first=<optimized out>, this=<synthetic > pointer>) > at /usr/include/c++/5/bits/stl_vector.h:404 > #20 sys_read (fp=0xffffa000032a6a00, iov=iov@entry=0xc420030180, > niov=niov@entry=1, > ---Type <return> to continue, or q <return> to quit--- > offset=offset@entry=-1, count=count@entry=0xc420030178) at > fs/vfs/vfs_syscalls.cc:269 > #21 0x0000000000420dec in pread (fd=<optimized out>, buf=<optimized out>, > count=<optimized out>, > offset=offset@entry=-1) at fs/vfs/main.cc:350 > #22 0x0000000000420f41 in read (fd=<optimized out>, buf=<optimized out>, > count=<optimized out>) > at fs/vfs/main.cc:368 > #23 0x00000000003d8634 in syscall (number=number@entry=0) at linux.cc:338 > #24 0x00000000003d8735 in syscall_wrapper (number=0) at linux.cc:394 > #25 0x000000000038a7d3 in syscall_entry () at arch/x64/entry.S:253 > #26 0x0000100001178e64 in syscall.Syscall () > at /home/wkozaczuk/tools/go-1.9.2/go/src/syscall/asm_linux_amd64.s:26 > #27 0x0000100001177497 in syscall.read (fd=6, p=..., n=842350659328, > err=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/syscall/zsyscall_ > linux_amd64.go:756 > #28 0x000010000117640b in syscall.Read (fd=6, p=..., n=56, err=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/syscall/syscall_unix.go:162 > #29 0x00001000011d3637 in internal/poll.(*FD).Read (fd=0xc420130400, > p=..., ~r1=0, ~r2=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/internal/poll/fd_unix.go:122 > #30 0x000010000122d7d4 in net.(*netFD).Read (fd=0xc420130400, p=..., > n=842350659784, err=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/net/fd_unix.go:202 > #31 0x00001000012397bf in net.(*conn).Read (c=0xc42000e350, b=..., ~r1=0, > ~r2=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/net/net.go:176 > #32 0x00001000012f4877 in net/http.(*connReader).Read (cr=0xc420138360, > p=..., n=0, err=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/net/http/server.go:753 > #33 0x00001000011f3eec in bufio.(*Reader).fill (b=0xc42004c1e0) > at /home/wkozaczuk/tools/go-1.9.2/go/src/bufio/bufio.go:97 > #34 0x00001000011f4ade in bufio.(*Reader).ReadSlice (b=0xc42004c1e0, > delim=10 '\n', line=..., err=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/bufio/bufio.go:338 > #35 0x00001000011f4d56 in bufio.(*Reader).ReadLine (b=0xc42004c1e0, > line=..., isPrefix=true, err=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/bufio/bufio.go:367 > #36 0x000010000129f8c2 in net/textproto.(*Reader).readLineSlice > (r=0xc420138390, ~r0=..., ~r1=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/net/textproto/reader.go:55 > #37 0x000010000129f7ed in net/textproto.(*Reader).ReadLine > (r=0xc420138390, ~r0=..., ~r1=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/net/textproto/reader.go:36 > #38 0x00001000012f116b in net/http.readRequest (b=0xc42004c1e0, > deleteHostHeader=false, req=0xc420136300, > err=...) at /home/wkozaczuk/tools/go-1.9.2/go/src/net/http/request.go: > 925 > #39 0x00001000012f5b8e in net/http.(*conn).readRequest (c=0xc42012e5a0, > ctx=..., w=0x0, err=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/net/http/server.go:933 > ---Type <return> to continue, or q <return> to quit--- > #40 0x00001000012f9950 in net/http.(*conn).serve (c=0xc42012e5a0, ctx=...) > at /home/wkozaczuk/tools/go-1.9.2/go/src/net/http/server.go:1739 > #41 0x0000100001169c81 in runtime.goexit () > at /home/wkozaczuk/tools/go-1.9.2/go/src/runtime/asm_amd64.s:2337 > #42 0x000000c42012e5a0 in ?? () > #43 0x00001000017238e0 in crypto/elliptic.p224ZeroModP63 () > #44 0x000000c420128d00 in ?? () > #45 0x0000000000000000 in ?? () > > Not sure if we are seeing same issue. > > I have also found this interesting series of articles about go internals - > https://blog.altoros.com/golang-part-1-main-concepts- > and-project-structure.html. Especially this part talks about resizable > stack implementaion in golang and bootstrap logic - > https://blog.altoros.com/golang-internals-part-5- > runtime-bootstrap-process.html. I am still digesting all that information > to see where in golang sourcecode put a debug statement that would prove > that indeed the underlying issue is as described in #808 > I think it will be hard to prove with printouts. If I understand correctly, Go knows where it needs more stack and enlarges the stack. But the problem is that when it calls a system call it doesn't think it needs stack space (in Linux, it doesn't) so the systemcall (which in OSv is just a function) is called with a tiny stack. I don't know how/where we can check that. Something which Benoit tried in the past is to compile Go with a huge default stack size, so the stack always starts at that default huge size and never needs to go - and he saw these problems going away. > and see if @hawxchen patch fixes it. I will keep you posted, > > Waldek > > PS, To see debug statements in go runtime modify the go source code for > example under $GOROOT/src/runtime/os_linux.go to add you println() call > and rebuild the app with this extra parameters: > > go build -a -v hello.go // this rebuilds all modified sources under > $GOROOT/src > > On Sunday, December 31, 2017 at 7:31:11 AM UTC-5, Nadav Har'El wrote: >> >> >> On Thu, Dec 28, 2017 at 7:09 PM, Waldek Kozaczuk <jwkoz...@gmail.com> >> wrote: >> >>> Also I have noticed my stack trace does not show Golang symbol names >>> like some example stacktraces in #850 do have. What am I missing to make >>> the stack traces to show Golang symbols? I dit verify with readelf that the >>> hello shared library has debugging info in it. Is it because >>> upload_manifest.py strips all *.so files? >>> >> >> It strips the something.so files into a new file something-stripped.so, >> so the original something.so is unharmed and used during debugging. >> >> However, you need to use "osv syms" in gdb to load all the shared objects >> into the debugger - otherwise the debugger only knows about the OSv >> kernel's symbols and only shows them. Is it possible you forgot that step? >> >> -- > You received this message because you are subscribed to the Google Groups > "OSv Development" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to osv-dev+unsubscr...@googlegroups.com. > For more options, visit https://groups.google.com/d/optout. > -- You received this message because you are subscribed to the Google Groups "OSv Development" group. To unsubscribe from this group and stop receiving emails from it, send an email to osv-dev+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/d/optout.
