Crashes with "pthread_create failed: Resource temporarily unavailable"

daer · 2016-10-18 14:50:10

Hi
have big problem to get NanoDLP to run in a stabile way. NanoDLP printer application very often crashes with "pthread_create failed: Resource temporarily unavailable" after a while when printing.
I have tried to restart raspberry pi just before start to print, but it doesn't help. It still crashes when printing.
I have tried to have the web page open on a PC or closed all browsers while printing. No differences.
I can see with uptime command that linux system haven't restarted, it shows expected time.

My setup is based on the sdcard image, just upgraded the printer application within it, e.g. run (wget http://www.nanodlp.com/nanodlp.tar.gz -O - | tar -C /home/pi -xz);cd /home/pi/printer;sudo ./setup.sh within a terminal.
My motors is controlled by an Arduino running GRBL. Running all moves with GCODE commands, no execute commands defined, shutter controlled bu arduino card using gcode commands, Projector turns on/off using a separate usb to rs232 converter and sens commands to projector.

Here is file i got when I pressed "Debug Info" button after I had restarted printer application. Before that I got "ERR_CONNECTION_REFUSED".
nanodlp.debug.-660712397.zip

I noticed that the printer.log in that zip file was the current 0 bytes long file. So here is two other log files that ends with the crash.
printer.log.1.zip
printer.log.6.zip

Shahin · 2016-10-22 07:45:52

Upgrade to latest version and let me know if the issue still persist.

daer · 2016-10-23 06:43:24

Upgraded to build 1257, still crashes.

I tested this time to have a ssh connection up. It didn't drop, still connected.
Browser was up and showing nanodlp dashboard.

Latest log
printer.log.1.zip

Is there anything I can do to help to find the cause of the problem? Running printer application in gdb? More logs?

daer · 2016-10-23 20:39:35

Have done one more run. This time with gdb.
Looks like there is increasing number of threads in the printer application.
After some layers there was 15 threads. Some hours later it have increased to 37, let it run for some more hours. Then it was 44.

Here is a dump in gdb of the threads

(gdb) info threads
Id Target Id Frame
44 Thread 0x611ff460 (LWP 2652) "printer" 0x000a8bac in ?? ()
43 Thread 0x619ff460 (LWP 2651) "printer" 0x000a8bac in ?? ()
42 Thread 0x621ff460 (LWP 2610) "printer" 0x000a8bac in ?? ()
41 Thread 0x629ff460 (LWP 2609) "printer" 0x000a8bac in ?? ()
40 Thread 0x631ff460 (LWP 2562) "printer" 0x000a8bac in ?? ()
39 Thread 0x639ff460 (LWP 2377) "printer" 0x000a8bac in ?? ()
38 Thread 0x641ff460 (LWP 2343) "printer" 0x000a8bac in ?? ()
37 Thread 0x649ff460 (LWP 2302) "printer" 0x000a8bac in ?? ()
36 Thread 0x651ff460 (LWP 2301) "printer" 0x000a8bac in ?? ()
35 Thread 0x659ff460 (LWP 2297) "printer" 0x000a8bac in ?? ()
34 Thread 0x661ff460 (LWP 2296) "printer" 0x000a8bac in ?? ()
33 Thread 0x669ff460 (LWP 2295) "printer" 0x000a8bac in ?? ()
32 Thread 0x671ff460 (LWP 2260) "printer" 0x000a8bac in ?? ()
31 Thread 0x679ff460 (LWP 2259) "printer" 0x000a8bac in ?? ()
30 Thread 0x681ff460 (LWP 2217) "printer" 0x000a8bac in ?? ()
29 Thread 0x689ff460 (LWP 2213) "printer" 0x000a8bac in ?? ()
28 Thread 0x691ff460 (LWP 2205) "printer" 0x000a8bac in ?? ()
27 Thread 0x699ff460 (LWP 2204) "printer" 0x000a8bac in ?? ()
26 Thread 0x6a1ff460 (LWP 2170) "printer" 0x000a8bac in ?? ()
25 Thread 0x6a9ff460 (LWP 2168) "printer" 0x000a8bac in ?? ()
24 Thread 0x6b1ff460 (LWP 2167) "printer" 0x000a8bac in ?? ()
23 Thread 0x6b9ff460 (LWP 2163) "printer" 0x000a8bac in ?? ()
22 Thread 0x6c1ff460 (LWP 2158) "printer" 0x0029d4e8 in ?? ()
21 Thread 0x6c9ff460 (LWP 2155) "printer" 0x000a8bac in ?? ()
20 Thread 0x6d1ff460 (LWP 2154) "printer" 0x000a8bac in ?? ()
19 Thread 0x6d9ff460 (LWP 2150) "printer" 0x000a8bac in ?? ()
18 Thread 0x6e1ff460 (LWP 2149) "printer" 0x000a8bac in ?? ()
17 Thread 0x6e9ff460 (LWP 2147) "printer" 0x000a8bac in ?? ()
16 Thread 0x6f1ff460 (LWP 2146) "printer" 0x000a8bac in ?? ()
15 Thread 0x703ff460 (LWP 2115) "printer" 0x000a8bac in ?? ()
14 Thread 0x6fbff460 (LWP 2116) "printer" 0x000a8bac in ?? ()
13 Thread 0x70cff460 (LWP 2101) "printer" 0x000a8bac in ?? ()
12 Thread 0x716ff460 (LWP 2100) "printer" 0x000a8bac in ?? ()
11 Thread 0x71eff460 (LWP 2099) "printer" 0x000a8bac in ?? ()
10 Thread 0x726ff460 (LWP 2097) "printer" 0x000a8bac in ?? ()
9 Thread 0x730ff460 (LWP 2096) "HCEC Notify" 0x76e59a40 in do_futex_wait (
isem=isem@entry=0x76f5aaf4 <cecservice_notify_available_event+24>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
8 Thread 0x738ff460 (LWP 2095) "HTV Notify" 0x76e59a40 in do_futex_wait (
isem=isem@entry=0x76f59d6c <tvservice_notify_available_event+24>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
7 Thread 0x740ff460 (LWP 2094) "HDispmanx Notif" 0x76e59a40 in do_futex_wait (
isem=isem@entry=0x76f5abf0 <dispmanx_notify_available_event+24>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
6 Thread 0x74abf460 (LWP 2093) "VCHIQ completio" 0x76dd502c in ioctl () at ../sysdeps/unix/syscall-template.S:81
5 Thread 0x75c40460 (LWP 2091) "printer" Cannot access memory at address 0xfffffffc
0x000a8bac in ?? ()
4 Thread 0x752ff460 (LWP 2092) "printer" Cannot access memory at address 0x0
0x000a8e60 in ?? ()
3 Thread 0x76440460 (LWP 2090) "printer" 0x000a8bac in ?? ()
2 Thread 0x76c40460 (LWP 2089) "printer" Cannot access memory at address 0x12
0x000a8bac in ?? ()
* 1 Thread 0x76fef210 (LWP 2086) "printer" 0x000a8bac in ?? ()

Shahin · 2016-10-25 07:02:14

It is an issue for a long time I try to reproduce locally as somebody else reported same issue. We come to conclusion it is something to do with tight loops!! (probably go gc)

Get ride of [[WaitForDoneMessage]] to see if it fix the issue or not.
If it fixed the issue we have a workaround. Go to setup page and scroll to the end there is value called sleep time (experimental) increase that value to level.

daer · 2016-10-26 04:42:19

Thanks for this.
I have tested to remove all [[WaitForDoneMessage]] and then it doesn't create any additional threads. After full run there was only 14 threads.

Unfortunately I don't have any success with increasing "sleep time". I hade increased it ten times to 1000000. After 15 minutes there was 17 threads, half hour later there was 20.

All test runs are from cold boot e.g. do the changes and then disconnect power from raspberry. Power it up and check new settings was stored correctly. Then start print from layer 0.

Shahin · 2016-10-27 07:39:04

I guess upgrading to go 1.7 make the problem worst.

Do you know which kind of message got surpassed by nanodlp? Your load is also quite high it should never pass 90% in normal conditions.

Shahin · 2016-10-27 07:58:17

Could you use gdb or pstack to see where those additional threads coming? Main issue with this bug is I could not reproduce it.

daer · 2016-10-27 09:54:32

No problem, but it doesn't give so muck information due to symbol information is stripped from applikation. I only get this information

(gdb) thread 16
[Switching to thread 16 (Thread 0x6f6bf460 (LWP 7402))]
#0 0x000a8bac in ?? ()
(gdb) info threads
Id Target Id Frame
17 Thread 0x6ecff460 (LWP 7403) "printer" Cannot access memory at address 0xfffffffc
0x000a8bac in ?? ()
* 16 Thread 0x6f6bf460 (LWP 7402) "printer" 0x000a8bac in ?? ()
15 Thread 0x6febf460 (LWP 7401) "printer" Cannot access memory at address 0x4
0x000a8e60 in ?? ()
14 Thread 0x706ff460 (LWP 7387) "printer" 0x0029d4e8 in ?? ()
13 Thread 0x70eff460 (LWP 7386) "printer" 0x000a8bac in ?? ()
12 Thread 0x716ff460 (LWP 7385) "printer" 0x000a8bac in ?? ()
11 Thread 0x71eff460 (LWP 7384) "printer" 0x000a8bac in ?? ()
10 Thread 0x726ff460 (LWP 7382) "printer" 0x000a8bac in ?? ()
9 Thread 0x730ff460 (LWP 7381) "HCEC Notify" 0x76e59a40 in do_futex_wait (
isem=isem@entry=0x76f5aaf4 <cecservice_notify_available_event+24>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
8 Thread 0x738ff460 (LWP 7380) "HTV Notify" 0x76e59a40 in do_futex_wait (
isem=isem@entry=0x76f59d6c <tvservice_notify_available_event+24>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
7 Thread 0x740ff460 (LWP 7379) "HDispmanx Notif" 0x76e59a40 in do_futex_wait (
isem=isem@entry=0x76f5abf0 <dispmanx_notify_available_event+24>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
6 Thread 0x74abf460 (LWP 7378) "VCHIQ completio" 0x76dd502c in ioctl () at ../sysdeps/unix/syscall-template.S:81
5 Thread 0x752ff460 (LWP 7377) "printer" 0x000a8bac in ?? ()
4 Thread 0x75c40460 (LWP 7376) "printer" 0x000a8bac in ?? ()
3 Thread 0x76440460 (LWP 7375) "printer" 0x000a8bac in ?? ()
2 Thread 0x76c40460 (LWP 7374) "printer" Cannot access memory at address 0x12
0x000a8bac in ?? ()
1 Thread 0x76fef210 (LWP 7371) "printer" 0x000a8bac in ?? ()
(gdb) bt
#0 0x000a8bac in ?? ()
#1 0x00073ca8 in _start ()

Shahin · 2016-10-27 14:33:13

Thank you for help.

I have updated the binary to include symbols. Please, wait until you get more than 30 threads.

daer · 2016-10-27 17:30:52

(gdb) info threads
Id Target Id Frame
33 Thread 0x671ff460 (LWP 7863) "printer" 0x000a7aa8 in runtime.futex ()
32 Thread 0x669ff460 (LWP 7864) "printer" 0x000a7aa8 in runtime.futex ()
31 Thread 0x679ff460 (LWP 7821) "printer" 0x000a7aa8 in runtime.futex ()
30 Thread 0x681ff460 (LWP 7820) "printer" 0x000a7aa8 in runtime.futex ()
29 Thread 0x689ff460 (LWP 7811) "printer" 0x000a7aa8 in runtime.futex ()
28 Thread 0x691ff460 (LWP 7810) "printer" 0x000a7aa8 in runtime.futex ()
27 Thread 0x6a1ff460 (LWP 7806) "printer" 0x000a7aa8 in runtime.futex ()
26 Thread 0x699ff460 (LWP 7807) "printer" 0x000a7aa8 in runtime.futex ()
25 Thread 0x6a9ff460 (LWP 7804) "printer" 0x000a7aa8 in runtime.futex ()
24 Thread 0x6b1ff460 (LWP 7802) "printer" 0x000a7aa8 in runtime.futex ()
23 Thread 0x6b9ff460 (LWP 7801) "printer" 0x000a7aa8 in runtime.futex ()
22 Thread 0x6c1ff460 (LWP 7775) "printer" 0x000a7aa8 in runtime.futex ()
21 Thread 0x6c9ff460 (LWP 7774) "printer" 0x000a7aa8 in runtime.futex ()
20 Thread 0x6d1ff460 (LWP 7771) "printer" 0x000a7aa8 in runtime.futex ()
19 Thread 0x6d9ff460 (LWP 7770) "printer" 0x000a7aa8 in runtime.futex ()
18 Thread 0x6e1ff460 (LWP 7764) "printer" 0x002a5e54 in syscall.Syscall ()
17 Thread 0x6e9ff460 (LWP 7765) "printer" 0x000a7aa8 in runtime.futex ()
16 Thread 0x6f1ff460 (LWP 7761) "printer" 0x000a7aa8 in runtime.futex ()
15 Thread 0x6fbbe460 (LWP 7759) "printer" 0x000a7aa8 in runtime.futex ()
14 Thread 0x703be460 (LWP 7758) "printer" 0x000a7aa8 in runtime.futex ()
13 Thread 0x70dff460 (LWP 7757) "printer" 0x000a7aa8 in runtime.futex ()
12 Thread 0x716ff460 (LWP 7743) "printer" 0x000a7aa8 in runtime.futex ()
11 Thread 0x71eff460 (LWP 7742) "printer" 0x000a7aa8 in runtime.futex ()
10 Thread 0x728ff460 (LWP 7740) "printer" 0x000a7aa8 in runtime.futex ()
9 Thread 0x730ff460 (LWP 7739) "HCEC Notify" 0x76e59a40 in do_futex_wait (
isem=isem@entry=0x76f5aaf4 <cecservice_notify_available_event+24>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
8 Thread 0x738ff460 (LWP 7738) "HTV Notify" 0x76e59a40 in do_futex_wait (
isem=isem@entry=0x76f59d6c <tvservice_notify_available_event+24>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
7 Thread 0x742bf460 (LWP 7737) "HDispmanx Notif" 0x76e59a40 in do_futex_wait (
isem=isem@entry=0x76f5abf0 <dispmanx_notify_available_event+24>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
6 Thread 0x74abf460 (LWP 7736) "VCHIQ completio" 0x76dd502c in ioctl () at ../sysdeps/unix/syscall-template.S:81
5 Thread 0x75c10460 (LWP 7734) "printer" 0x000a7aa8 in runtime.futex ()
4 Thread 0x752ff460 (LWP 7735) "printer" 0x000a7d4c in runtime.epollwait ()
3 Thread 0x76410460 (LWP 7733) "printer" 0x000a7aa8 in runtime.futex ()
2 Thread 0x76c50460 (LWP 7732) "printer" 0x000a7aa8 in runtime.futex ()
* 1 Thread 0x76fef210 (LWP 7729) "printer" 0x000a7aa8 in runtime.futex ()

(gdb) thread 22
[Switching to thread 22 (Thread 0x6c1ff460 (LWP 7775))]
#0 0x000a7aa8 in runtime.futex ()
(gdb) bt
#0 0x000a7aa8 in runtime.futex ()
#1 0x00074600 in runtime.futexsleep ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

(gdb) thread 20
[Switching to thread 20 (Thread 0x6d1ff460 (LWP 7771))]
#0 0x000a7aa8 in runtime.futex ()
(gdb) bt
#0 0x000a7aa8 in runtime.futex ()
#1 0x00074600 in runtime.futexsleep ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb)

(gdb) thread 2
[Switching to thread 2 (Thread 0x76c50460 (LWP 7732))]
#0 0x000a7aa8 in runtime.futex ()
(gdb) bt
#0 0x000a7aa8 in runtime.futex ()
#1 0x00074690 in runtime.futexsleep ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb)

Just to see how a normal thread looks like. This goes down all way down to pthread_create

[Switching to thread 8 (Thread 0x738ff460 (LWP 7738))]
#0 0x76e59a40 in do_futex_wait (isem=isem@entry=0x76f59d6c <tvservice_notify_available_event+24>)
at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
48 in ../nptl/sysdeps/unix/sysv/linux/sem_wait.c
(gdb) bt
#0 0x76e59a40 in do_futex_wait (isem=isem@entry=0x76f59d6c <tvservice_notify_available_event+24>)
at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:48
#1 0x76e59af4 in __new_sem_wait (sem=0x76f59d6c <tvservice_notify_available_event+24>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:69
#2 0x76f40ac4 in tvservice_notify_func () from /opt/vc/lib/libbcm_host.so
#3 0x76cddcc4 in vcos_thread_entry (arg=0x76f59d80 <tvservice_notify_task>)
at /home/dc4/projects/staging/userland/interface/vcos/pthreads/vcos_pthreads.c:144
#4 0x76e52e90 in start_thread (arg=0x738ff460) at pthread_create.c:311
#5 0x76ddc698 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/nptl/../clone.S:92 from /lib/arm-linux-gnueabihf/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

And one more
(gdb) thread 18
[Switching to thread 18 (Thread 0x6e1ff460 (LWP 7764))]
#0 0x002a5e54 in syscall.Syscall ()
(gdb) bt
#0 0x002a5e54 in syscall.Syscall ()
#1 0x002a3444 in syscall.read ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

So it looks like gdb say corrupt stack when it goes somewhere from user space to kernel space

Shahin · 2016-10-27 21:46:42

Please, update to the latest version and try again.

daer · 2016-10-28 06:41:27

Looks promising. Have run it for one hour now and no extra threads.
I will continue the run and keep you updated.

daer · 2016-10-28 12:44:01

I can confirm that build 1259 works.
2402 layers, no additional threads when finished.

Thanks.

daer · 2016-10-28 15:37:40

One more positive thing.
This build also seems to fix the high cpu load spikes that there was before.
Now high cpu load isn't observed neither when running top or in the cpu graph on the dashboard.
Before there could be spikes, just around second long, that was over 100%.

Shahin · 2016-10-28 16:40:46

Good to know that, thank you for the help

adam · 2016-11-07 18:11:01

After some time off the forums i have just stumbled across this. I'm glad that someone with more experience than me had the same problem so it could be resolved.
@daer: thanks for helping out
@shahin: as always, thanks for keeping at it

cheers

mhackney · 2016-11-09 02:55:10

I have also been experiencing nanoDLP crashes - very frequently. Build 1261 installed on a new RPi. What data or logs can I collect to help?

Shahin · 2016-11-09 06:34:28

When your printer crashes? go to setup page / tools tab and press debug button.

mhackney · 2016-11-09 18:35:06

I took a look at the debug files. I see issues with memory management (out of memory, files not loaded). I also see that my network SSID, my local IP address and other information that I would not want to send to someone are in the log files. I'm happy to send you specific files that I scrub if it would help or if you list the files and what personal information is contained in them so I can scrub them, I'd do that too. But I am not comfortable sending the entire debug zip without knowing exactly what personal information is in there.

Shahin · 2016-11-09 20:43:33

printer.log will be enough for basic troubleshooting. If it is empty share printer.log.gz.

nanoDLP

#1 2016-10-18 14:50:10

Crashes with "pthread_create failed: Resource temporarily unavailable"

#2 2016-10-22 07:45:52

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#3 2016-10-23 06:43:24

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#4 2016-10-23 20:39:35

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#5 2016-10-25 07:02:14

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#6 2016-10-26 04:42:19

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#7 2016-10-27 07:39:04

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#8 2016-10-27 07:58:17

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#9 2016-10-27 09:54:32

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#10 2016-10-27 14:33:13

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#11 2016-10-27 17:30:52

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#12 2016-10-27 21:46:42

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#13 2016-10-28 06:41:27

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#14 2016-10-28 12:44:01

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#15 2016-10-28 15:37:40

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#16 2016-10-28 16:40:46

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#17 2016-11-07 18:11:01

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#18 2016-11-09 02:55:10

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#19 2016-11-09 06:34:28

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#20 2016-11-09 18:35:06

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

#21 2016-11-09 20:43:33

Re: Crashes with "pthread_create failed: Resource temporarily unavailable"

Board footer