Copyright © https://mongoose-os.com

Mongoose OS Forum

frame
ATTENTION! This forum has moved to:

https://community.mongoose-os.com

Do not post any new messages.

Javascript Guru panic on slight changes

I have a working javascript program of about 400 lines, calling low-level c routines of about 250 lines. It has a partial console output of:

[May 31 12:49:31.849] unpacked
[May 31 12:49:33.896] Start
[May 31 12:49:33.957] mgos_aws_shadow_init AWS Device Shadow requires MQTT
[May 31 12:49:33.957] mongoose_poll New heap free LWM: 2596
[May 31 12:49:36.956] Now 1514797106.832415 Tick uptime: 8.918137 {"free_ram":26916,"total_ram":186248}
[May 31 12:49:39.970] Now 1514797109.835998 Tick uptime: 11.921763 {"free_ram":26880,"total_ram":186248}
[May 31 12:49:40.906] skedon: 1
[May 31 12:49:42.951] Now 1514797112.833060 Tick uptime: 14.918868 {"free_ram":26524,"total_ram":186220}
[May 31 12:49:45.949] Now 1514797115.832890 Tick uptime: 17.918734 {"free_ram":26472,"total_ram":186220}
[May 31 12:49:48.963] Now 1514797118.832977 Tick uptime: 20.918841 {"free_ram":26472,"total_ram":186220}

When I add a single javascript variable assignment:
let GMT2018=1514764800;
(and without actually using GMT2018 anywhere in the code), I get the following panic:

May 31 12:34:26.211] unpacked
[May 31 12:34:26.489] E:M 12216
[May 31 12:34:26.504] Heap summary for capabilities 0x00001800:
[May 31 12:34:26.505] At 0x3ffbbb28 len 8192 free 0 allocated 8000 min_free 0
[May 31 12:34:26.515] largest_free_block 0 alloc_blocks 40 free_blocks 0 total_blocks 40
[May 31 12:34:26.518] At 0x3ffb2730 len 22736 free 0 allocated 22456 min_free 0
[May 31 12:34:26.523] largest_free_block 0 alloc_blocks 62 free_blocks 0 total_blocks 62
[May 31 12:34:26.528] At 0x3ffaff10 len 240 free 0 allocated 196 min_free 0
[May 31 12:34:26.538] largest_free_block 0 alloc_blocks 3 free_blocks 0 total_blocks 3
[May 31 12:34:26.541] At 0x3ffd8fa0 len 28768 free 0 allocated 28464 min_free 0
[May 31 12:34:26.547] largest_free_block 0 alloc_blocks 68 free_blocks 0 total_blocks 68
[May 31 12:34:26.552] At 0x3ffe0440 len 15296 free 0 allocated 14752 min_free 0
[May 31 12:34:26.562] largest_free_block 0 alloc_blocks 128 free_blocks 0 total_blocks 128
[May 31 12:34:26.563] At 0x3ffe4350 len 113840 free 7692 allocated 104788 min_free 7692
[May 31 12:34:26.571] largest_free_block 6560 alloc_blocks 311 free_blocks 21 total_blocks 332
[May 31 12:34:26.572] Totals:
[May 31 12:34:26.580] free 7756 allocated 178592 min_free 7688 largest_free_block 6560
[May 31 12:34:26.580] E:M 12247
[May 31 12:34:26.583] Heap summary for capabilities 0x00001800:
[May 31 12:34:26.589] At 0x3ffbbb28 len 8192 free 0 allocated 8000 min_free 0
[May 31 12:34:26.598] largest_free_block 0 alloc_blocks 40 free_blocks 0 total_blocks 40
[May 31 12:34:26.604] At 0x3ffb2730 len 22736 free 0 allocated 22456 min_free 0
[May 31 12:34:26.606] largest_free_block 0 alloc_blocks 62 free_blocks 0 total_blocks 62
[May 31 12:34:26.611] At 0x3ffaff10 len 240 free 0 allocated 196 min_free 0
[May 31 12:34:26.620] largest_free_block 0 alloc_blocks 3 free_blocks 0 total_blocks 3
[May 31 12:34:26.623] At 0x3ffd8fa0 len 28768 free 0 allocated 28464 min_free 0
[May 31 12:34:26.629] largest_free_block 0 alloc_blocks 68 free_blocks 0 total_blocks 68
[May 31 12:34:26.634] At 0x3ffe0440 len 15296 free 0 allocated 14752 min_free 0
[May 31 12:34:26.644] largest_free_block 0 alloc_blocks 128 free_blocks 0 total_blocks 128
[May 31 12:34:26.647] At 0x3ffe4350 len 113840 free 7692 allocated 104788 min_free 7688
[May 31 12:34:26.654] largest_free_block 6560 alloc_blocks 311 free_blocks 21 total_blocks 332
[May 31 12:34:26.654] Totals:
[May 31 12:34:26.663] free 7756 allocated 178592 min_free 7688 largest_free_block 6560
[May 31 12:34:26.663] E:M 12119
[May 31 12:34:26.666] Heap summary for capabilities 0x00001800:
[May 31 12:34:26.671] At 0x3ffbbb28 len 8192 free 0 allocated 8000 min_free 0
[May 31 12:34:26.681] largest_free_block 0 alloc_blocks 40 free_blocks 0 total_blocks 40
[May 31 12:34:26.682] At 0x3ffb2730 len 22736 free 0 allocated 22456 min_free 0
[May 31 12:34:26.690] largest_free_block 0 alloc_blocks 62 free_blocks 0 total_blocks 62
[May 31 12:34:26.694] At 0x3ffaff10 len 240 free 0 allocated 196 min_free 0
[May 31 12:34:26.702] largest_free_block 0 alloc_blocks 3 free_blocks 0 total_blocks 3
[May 31 12:34:26.706] At 0x3ffd8fa0 len 28768 free 0 allocated 28464 min_free 0
[May 31 12:34:26.711] largest_free_block 0 alloc_blocks 68 free_blocks 0 total_blocks 68
[May 31 12:34:26.718] At 0x3ffe0440 len 15296 free 0 allocated 14752 min_free 0
[May 31 12:34:26.723] largest_free_block 0 alloc_blocks 128 free_blocks 0 total_blocks 128
[May 31 12:34:26.735] At 0x3ffe4350 len 113840 free 7692 allocated 104788 min_free 7688
[May 31 12:34:26.739] largest_free_block 6560 alloc_blocks 311 free_blocks 21 total_blocks 332
[May 31 12:34:26.739] Totals:
[May 31 12:34:26.776] free 7756 allocated 178592 min_free 7684 largest_free_block 6560
[May 31 12:34:26.783] Guru Meditation Error: Core 0 panic'ed (StoreProhibited)
[May 31 12:34:26.784] . Exception was unhandled.
[May 31 12:34:26.784] Core 0 register dump:
[May 31 12:34:26.784] PC : 0x4000c350 PS : 0x00060430 A0 : 0x801000b0 A1 : 0x3ffe23a0
[May 31 12:34:26.785] A2 : 0x00000000 A3 : 0x3fffdc64 A4 : 0x00000564 A5 : 0x00000000
[May 31 12:34:26.785] A6 : 0x30303030 A7 : 0x66666630 A8 : 0x30303263 A9 : 0x00000000
[May 31 12:34:26.816] A10 : 0x00000000 A11 : 0x00000001 A12 : 0x3ffe2380 A13 : 0x3ffe2388
[May 31 12:34:26.827] A14 : 0x00000001 A15 : 0x0000000a SAR : 0x00000008 EXCCAUSE: 0x0000001d
[May 31 12:34:26.828] EXCVADDR: 0x00000000 LBEG : 0x4000c349 LEND : 0x4000c36b LCOUNT : 0x00000055
[May 31 12:34:26.828]
[May 31 12:34:26.828] Backtrace: 0x4000c350 0x401000ad 0x40101eff 0x4010337b 0x40103813 0x4010386b 0x400fa2ae 0x400e279d 0x400e2bfd 0x400e28d0 0x40082d3
[May 31 12:34:26.829] --- BEGIN CORE DUMP ---
[May 31 12:34:26.829] mos: catching core dump

The description of this panic is the simplest instance of this issue. Other similar panics occur with other slightly different arrangements of code. It must be some capacity, memory management or scheduling issue, however I am at a loss to figure out what factors may be involved. Also, the amount of memory that is consumed by such a small program seems much too large. Can any one point me in the right direction to solve this?

Thanks all,

JSW

Comments

  • tripflextripflex Orlando, FL

    Did you let it continue running and then analyze the core dump to see what it says?

  • jstevewoodjstevewood California

    I could. It's completely predictable. However I have no idea on where to find the core dump, and how to analyze it. Can you tell me what to look for?

    Thanks,

    JSW

  • nliviunliviu Romania

    If you wait after mos: catching core dump, you will see the core dump analisys.
    Recent versions (latest and 2.2) analyze the core dump automatically.

    Thanked by 1jstevewood
  • jstevewoodjstevewood California

    Thanks nliviu.

    I am using version 2.2, and here's what happens after a Guru panic:

    [Jun 14 11:24:36.593] --- BEGIN CORE DUMP ---
    [Jun 14 11:24:36.593] mos: catching core dump
    [Jun 14 11:25:31.141] ---- END CORE DUMP ----
    [Jun 14 11:25:31.174] mos: wrote to C:\Users\Steve\AppData\Local\Temp\core--ESP32-20180614-112531.491532781 (628345 bytes)
    [Jun 14 11:25:31.176] mos: analyzing core dump
    Using ELF file at: C:\Mong\DSTtest5New6\build\objs\fw.elf
    Using Docker image: docker.cesanta.com/esp32-build:3.0-rc1-r8
    Running docker run --rm -v C:\Mong\blahblahblah................................
    [Jun 14 11:25:31.257] mos: exec: "docker": executable file not found in %PATH%
    [Jun 14 11:25:31.259] Rebooting...

    This process will repeat indefinitely until the program successfully starts (about 1 time in 6).

    I think that for a proper analysis, I have to add access to or reconfigure docker. How do I do that?

    Thanks,

    JSW

  • nliviunliviu Romania
    edited June 2018

    Ahhh. You need to install docker.

    The line mongoose_poll New heap free LWM: 2596 shows that you are very low on memory.
    Later on, when the system needs to allocate some more memory, there is no memory free:

    [May 31 12:34:26.504] Heap summary for capabilities 0x00001800:
    [May 31 12:34:26.505] At 0x3ffbbb28 len 8192 free 0 allocated 8000 min_free 0
    [May 31 12:34:26.515] largest_free_block 0 alloc_blocks 40 free_blocks 0 total_blocks 40
    [May 31 12:34:26.518] At 0x3ffb2730 len 22736 free 0 allocated 22456 min_free 0
    
  • jstevewoodjstevewood California

    Hi nliviu,

    Thank you for help.

    The cause of this problem is that I am running out of memory? How can this be? I have a timer that indicates {"free_ram:26916, "total_ram:186248}. The free ram number keeps changing slightly, but it never drops below 26,472. I guess I don't understand the meaning of these two numbers, and how they are related to the mongoose_poll.
    Is there any place where this interaction is described?

    My project consists of about 400 lines of Javascript, with ffi calls to about 200 lines of C functions. The C functions have only 256 bytes of static variables, and very small dynamic loads. So, any memory efficiency issue has to be in Javascript. There, I have about 80 variables, 12 strings of16 bytes each, 1 string of 2560 bytes, 1 string of 1920 bytes, 2 arrays of 12 elements each, 1 array of 14 objects(each object of 12 elements in length). Not all of these items are needed during all phases of execution, but this does not seem like an extreme usage of memory.

    How is mJS memory allocated?
    Is there a way of freeing no-longer-needed Javascript variables?
    Do you have any memory efficiency instructions for mJS?

    Thanks,

    JSW

  • nliviunliviu Romania

    I suppose you use Sys.free_ram() which maps to mgos_get_free_heap_size and mongoose_poll reports mgos_get_min_free_heap_size which I suppose means the largest amount that can be allocated.

    There is memory allocated, let's say, behind the scene by the API calls, eg. ssl hanshake.

    Could you post a full console log on pastebin or similar? The snipptes you posted here are to short.

  • jstevewoodjstevewood California

    Booting firmware...
    All done!
    Using port COM3
    [Jun 15 13:55:55.999] [0;32mI (645) esp_image: segment 3: paddr=0x0016fed4 vaddr=0x3ffc0aac size=0x028f4 ( 10484) load[0m
    [Jun 15 13:55:56.004] [0;32mI (649) esp_image: segment 4: paddr=0x001727d0 vaddr=0x40080000 size=0x00400 ( 1024) load[0m
    [Jun 15 13:55:56.006] [0;32mI (652) esp_image: segment 5: paddr=0x00172bd8 vaddr=0x40080400 size=0x1576c ( 87916) load[0m
    [Jun 15 13:55:56.038] [0;32mI (696) esp_image: segment 6: paddr=0x0018834c vaddr=0x400c0000 size=0x00034 ( 52) load[0m
    [Jun 15 13:55:56.084] [0;32mI (709) boot: Loaded app from partition at offset 0x10000[0m
    [Jun 15 13:55:56.087] [0;32mI (709) boot: Disabling RNG early entropy source...[0m
    [Jun 15 13:55:56.088] [0;32mI (710) cpu_start: Pro cpu up.[0m
    [Jun 15 13:55:56.088] [0;32mI (713) cpu_start: Single core mode[0m
    [Jun 15 13:55:56.089] [0;32mI (718) heap_init: Initializing. RAM available for dynamic allocation:[0m
    [Jun 15 13:55:56.089] [0;32mI (724) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM[0m
    [Jun 15 13:55:56.090] [0;32mI (730) heap_init: At 3FFD8FA0 len 00007060 (28 KiB): DRAM[0m
    [Jun 15 13:55:56.103] [0;32mI (737) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM[0m
    [Jun 15 13:55:56.104] [0;32mI (743) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[0m
    [Jun 15 13:55:56.104] [0;32mI (749) heap_init: At 40095B6C len 0000A494 (41 KiB): IRAM[0m
    [Jun 15 13:55:56.105] [0;32mI (755) cpu_start: Pro cpu start user code[0m
    [Jun 15 13:55:56.114] [0;32mI (102) cpu_start: Starting scheduler on PRO CPU.[0m
    [Jun 15 13:55:56.145] mgos_init2 DSTtest5New6 1.0 (20180531-175302/???)
    [Jun 15 13:55:56.146] mgos_init2 Mongoose OS 2018053117 (20180531-175259/???)
    [Jun 15 13:55:56.146] mgos_init2 CPU: 160 MHz, RAM: 157672 total, 118708 free
    [Jun 15 13:55:56.146] mg_lwip_if_init Mongoose 6.11, LwIP 1.5.0
    [Jun 15 13:55:56.146] mg_ssl_if_init mbed TLS 2.8.0
    [Jun 15 13:55:56.148] mgos_hal_freertos_pr ESP-IDF v3.0-rc1-r9
    [Jun 15 13:55:56.152] mgos_hal_freertos_pr Boot partition: app_0; flash: 4M
    [Jun 15 13:55:56.161] mgos_vfs_dev_open esp32part ({"label": "fs_0", "subtype": 130}) -> 0x3ffe306c
    [Jun 15 13:55:56.177] mgos_vfs_mount Mount SPIFFS @ / (dev 0x3ffe306c, opts {"encr": false}) -> 0x3ffe307c
    [Jun 15 13:55:56.284] mgos_vfs_mount /: size 233681, used: 174947, free: 58734
    [Jun 15 13:55:56.360] mgos_sys_config_init MAC: 30AEA43C6AC8
    [Jun 15 13:55:56.372] mgos_sys_config_init WDT: 30 seconds
    [Jun 15 13:55:56.374] [0;32mI (611) BTDM_INIT: BT controller compile version [48877dc]
    [Jun 15 13:55:56.374] [0m
    [Jun 15 13:55:56.610] [0;33mW (851) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration[0m
    [Jun 15 13:55:56.795] [0;32mI (1021) phy: phy_version: 386.0, 67c798f, Mar 14 2018, 16:34:06, 0, 2[0m
    [Jun 15 13:55:56.840] start_advertising BT device name esp32_3C6AC8
    [Jun 15 13:55:56.841] esp32_gap_ev_handler BLE advertising started
    [Jun 15 13:55:56.843] mgos_bt_common_init Bluetooth init ok, pairing enabled, 0 paired devices
    [Jun 15 13:55:56.853] esp32_bt_gatts_ev Starting BT service 5f6d4f53-5f43-4647-5f53-56435f49445f
    [Jun 15 13:55:56.864] esp32_bt_gatts_ev Starting BT service 5f6d4f53-5f44-4247-5f53-56435f49445f
    [Jun 15 13:55:56.870] mgos_ota_shadow_init OTA over shadow initialised
    [Jun 15 13:55:56.880] mgos_wifi_setup WiFi mode: AP
    [Jun 15 13:55:56.880] esp32_wifi_set_mode WiFi mode: AP
    [Jun 15 13:55:56.883] E (1131) wifi: esp_wifi_set_mode 792 wifi is not init
    [Jun 15 13:55:56.888] I (1131) wifi: wifi firmware version: c09b606
    [Jun 15 13:55:56.900] I (1141) wifi: config NVS flash: enabled
    [Jun 15 13:55:56.900] I (1141) wifi: config nano formating: disabled
    [Jun 15 13:55:56.916] I (1161) wifi: Init dynamic tx buffer num: 32
    [Jun 15 13:55:56.921] I (1161) wifi: Init data frame dynamic rx buffer num: 64
    [Jun 15 13:55:56.927] I (1171) wifi: Init management frame dynamic rx buffer num: 64
    [Jun 15 13:55:56.938] I (1171) wifi: wifi driver task: 3ffe4bdc, prio:23, stack:4096
    [Jun 15 13:55:56.941] I (1181) wifi: Init static rx buffer num: 10
    [Jun 15 13:55:56.941] I (1181) wifi: Init dynamic rx buffer num: 0
    [Jun 15 13:55:56.947] mgos_wifi_dev_ap_set WiFi AP: SSID RS1234, channel 6
    [Jun 15 13:55:57.794] mgos_wifi_dev_ap_set WiFi AP IP: 192.168.4.1/255.255.255.0 gw 192.168.4.1, DHCP range 192.168.4.2 - 192.168.4.100
    [Jun 15 13:55:57.805] I (2051) wifi: mode : softAP (30:ae:a4:3c:6a:c9)
    [Jun 15 13:55:57.814] mgos_wifi_dev_ap_set WiFi AP: SSID RS1234, channel 6
    [Jun 15 13:55:57.820] event_handler event: 13
    [Jun 15 13:55:57.827] mgos_http_server_ini HTTP server started on [80]
    [Jun 15 13:55:57.836] mgos_ota_http_client Init done, ota_lib=(null), ota handler 1
    [Jun 15 13:55:57.847] esp32_bt_gatts_ev Starting BT service 5f6d4f53-5f52-5043-5f53-56435f49445f
    [Jun 15 13:55:57.854] mg_rpc_channel_mqtt 0x3ffeb8bc esp32_3C6AC8/rpc
    [Jun 15 13:55:57.858] mg_rpc_channel_uart 0x3ffebf50 UART0
    [Jun 15 13:55:57.869] mgos_init Init done, RAM: 186944 total, 80524 free, 80524 min free
    [Jun 15 13:55:58.366] fake Unix time: 1514797100.002645
    [Jun 15 13:55:59.489] sked[i] : 2 0101010100000000x 4 \x80 \xb5 \x80@ 1 3 3600 7200 10800 604800 10 1
    [Jun 15 13:55:59.534] sked[i] : 3 0001000000000000x 1 \x80 2 3 10800 14400 18000 604800 10 1
    [Jun 15 13:55:59.579] sked[i] : 4 0001000100000000x 4 \x80@\xb5

    \x80\x80 3 3 3600 7200 10800 604800 10 1
    [Jun 15 13:55:59.624] sked[i]   : 5 0010101000000000x 1 \x80@ 4 2 21600 25200 99999 604800 10 1
    [Jun 15 13:55:59.669] sked[i]   : 6 1000000010000000x 4   \x80\x80\xb5\xa0\x80\xc0 5 1 18200 99999 99999 0 10 1
    [Jun 15 13:55:59.715] sked[i]   : 7 1000000000010001x 1 \x80
    6 2 21600 25200 99999 86400 10 1
    [Jun 15 13:55:59.761] sked[i] : 8 1000000000100001x 4 \x80\xc0\xb5\xe0\x80 7 1 18200 99999 99999 172800 10 1
    [Jun 15 13:55:59.805] sked[i] : 9 1000000000100010x 1 \x80\x80 8 2 21600 25200 99999 172800 10 1
    [Jun 15 13:55:59.849] sked[i] : 10 1000000000010010x 4 \x80 \xb5 \x80@ 9 1 18000 99999 99999 86400 10 1
    [Jun 15 13:55:59.910] sked[i] : 11 0000000100000000x 1 \x80\xa0 10 2 21600 25200 99999 604800 10 1
    [Jun 15 13:55:59.954] sked[i] : 12 0011000000000000x 4 \x80@\xb5`\x80\x80 9 1 18000 99999 99999 604800 10 1
    [Jun 15 13:55:59.999] sked[i] : 13 0110110000000000x 1 \x80\xc0 8 2 21600 25200 99999 604800 10 1
    [Jun 15 13:56:00.051] sked[i] : 14 0101010100000000x 4 \x80\x80\xb5\xa0\x80\xc0 7 1 18000 99999 99999 604800 10 1
    [Jun 15 13:56:00.110] sked[i] : 15 0101010100000000x 1 \x80\xe0 6 2 21600 25200 99999 604800 10 1
    [Jun 15 13:56:00.110] unpacked
    [Jun 15 13:56:00.736] raw64 version of sprinkler.bak: 0000fffc200200002001514764800-28800UnNamed .........
    [Jun 15 13:56:00.743] fileupdater lastMCC: 1514764800
    [Jun 15 13:56:00.747] fileupdater thisMCC: 1525995357
    [Jun 15 13:56:00.788] sprinklerfilename: sprinkler1514764800.old
    [Jun 15 13:56:01.848] waterfilename: WaterUse1514764800.txt
    [Jun 15 13:56:01.893] mccfilestring: [1300000000,1546500000,1546600000,1514764800]
    [Jun 15 13:56:01.968] mccupdatesstring: [1300000000,1546500000,1546600000,1514764800]
    [Jun 15 13:56:01.971] mccupdate[i] 0 1300000000
    [Jun 15 13:56:01.973] mccout:
    [Jun 15 13:56:01.982] mccfilestring: [1546500000,1546600000,1514764800]
    [Jun 15 13:56:02.079] mccfilestring: 1300000000
    [Jun 15 13:56:02.080] mccupdate[i] 1 1546600000
    [Jun 15 13:56:02.080] mccupdate[i] 2 1514764800
    [Jun 15 13:56:02.156] Start
    [Jun 15 13:56:02.201] mgos_aws_shadow_init AWS Device Shadow requires MQTT
    [Jun 15 13:56:02.201] mongoose_poll New heap free LWM: 2596
    [Jun 15 13:56:05.216] Now 1514797106.830890 Tick uptime: 8.912226 {"free_ram":26912,"total_ram":186252}
  • jstevewoodjstevewood California

    Hi nliviu,

    Thanks for your quick response. The previous post shows a successful bootup all the way from power on to operational.

    I tried replacing mgos_get_free_heap_size with mgos_get_min_free_heap_size in api_sys.js. (It seem that this would be a better continuous monitor). I got a bad ffi signature error message.

    Any thoughts?

    JSW

  • nliviunliviu Romania

    You can't modify api_sys.js like this. The build process scans the js files for ffi-ed functions and creates the necessary structures for mjs.
    Try

    let get getInfo = function() {
      return JSON.stringify({
        total_ram: Sys.total_ram(),
        free_ram: Sys.free_ram(),
        min_free: ffi('int mgos_get_min_free_heap_size()`)()
      });
    };
    

    rebuild and flash.

Sign In or Register to comment.