[Glass] JIT / native code [WAS] Re: Weird slowdown with a comparison
Mariano Martinez Peck
marianopeck at gmail.com
Fri Dec 27 09:29:12 PST 2013
On Tue, Dec 17, 2013 at 12:28 PM, Mariano Martinez Peck <
marianopeck at gmail.com> wrote:
> Thanks Dale. So..I can confirm that enabling the JIT in the seaside gems
> increases performance quite a lot in my report. They decreased to half :)
> Now... John pasted this:
>
> # This is set to allow breakpoints to be used ....
>
> # For production usage, set GEM_NATIVE_CODE_ENABLED
>
> # in the conf file for the appropriate gem
>
> # (see
>
> # $GEMSTONE/seaside/etc/maintenance30.conf
>
> # $GEMSTONE/seaside/etc/seaside30.conf)
>
> #
>
> GEM_NATIVE_CODE_ENABLED = FALSE;
>
>
> Notice the *"This is set to allow breakpoints to be used".*
> The admin guide says:* "If any breakpoints are set in any methods, native
> code is disabled. Native code is re-enabled when all breakpoints have been
> removed"*
>
> For me, I have 2 scenarios:
>
> 1) if someone press "remote debug" in a seaside walkback I really want to
> be able to debug that with GemTools from the ObjectLog
> 2) if I put a halt somewhere in the code and I want to debug that later
>
> I tested both enabling the JIT. 1) seems to work even with the JOT. 2)
> does not work in the sense that the code is NOT interrupted by the halt, it
> seems to simply continue executing and ignore it. So I cannot see how this
> is exactly related to the above sentences. I think I do see the *"This is
> set to allow breakpoints to be used". *But I cannot understand the "* "If
> any breakpoints are set in any methods, native code is disabled. Native
> code is re-enabled when all breakpoints have been removed"*"
> If I understand this, it means that native code would be disabled
> automatically, the VM would start to interpret, and hence I would expect
> the halt to interrupt. But that doesn't happen in my case...the halt is
> ignored.
>
> Any clarification of the real implications of enabling the JIT would be
> appreciated.
>
> Thanks!
>
>
I continue my research with this topic. In my server (Linux box),
everything works as described above. But....in my local OSX GemStone I have
a real crash. I put a halt in a callback of Seaside. The adaptor is
FastCGI. I clicked Remote Debug and the stack is written in the ObjectLog.
Now...if I try to "Debug" and select that entry from the object log, my gem
crash.
SAME test case in the Linux-based works perfectly.
Of course, if I switch to GEM_NATIVE_CODE_ENABLED = FALSE;
in my /opt/gemstone/product/seaside/etc/seaside30.conf then I can debug
without problem. So in fact it is a native code problem.
In my case is not a big deal because locally I can put it in false, and the
server works fine with true. But I thought about reporting it in case it is
useful for you to find the cause.
Here is the log:
14:04 mariano at MacBook-Pro-de-Mariano /opt/gemstone/log
% cat gemnetobject25860.log
_____________________________________________________________________________
| NetLDI Child Task
|
|
|
| CLIENTHOST: MacBook-Pro-de-Mariano.local
|
| VERSION: 3.1.0.4, Mon Jun 17 13:14:05 2013
|
| BUILD: gss64_3_1_0_x_branch-31024
|
| BUILT FOR: Darwin (Mac)
|
| MODE: 64 bit
|
| RUNNING ON: 2-CPU MacBook-Pro-de-Mariano.local x86_64 (Darwin 12.5.0 )
2530MHz
| MacBookPro5,1 2048MB
|
| PROCESS ID: 25860 DATE: 12/27/2013 14:03:29 ART
|
| USER IDS: REAL=mariano (501) EFFECTIVE=mariano (501)
|
| COMMAND:
/opt/gemstone/GemStone64Bit3.1.0.4-i386.Darwin/sys/gemnetobject |
| TCP 63159 30
|
|_____________________________________________________________________________|
exeConfig -d path
[Info]: the hostname is: MacBook-Pro-de-Mariano.local
GEMSTONE is: "/opt/gemstone/product"
gem's location is: /opt/gemstone/product/sys
system config file is: /opt/gemstone/product/seaside/data/system.conf
executable config file is: /opt/gemstone/product/seaside/data
gem's arguments are: TCP 63159 30
_____________________________________________________________________________
| GemStone/S64 Object-Oriented Data Management System
|
| Copyright (C) VMware, Inc. 1986-2013
|
| All rights reserved.
|
| Covered by U.S Patents:
|
| 6,256,637 Transactional virtual machine architecture
|
| 6,360,219 Object queues with concurrent updating
|
| 6,567,905 Generational Garbage Collector.
|
| 6,681,226 Selective Pessimistic Locking for a Concurrently Updateable
Database
+-----------------------------------------------------------------------------+
| PROGRAM: GEM, GemStone Session Process
|
| VERSION: 3.1.0.4, Mon Jun 17 13:14:05 2013
|
| BUILD: gss64_3_1_0_x_branch-31024
|
| BUILT FOR: Darwin (Mac)
|
| MODE: 64 bit
|
| RUNNING ON: 2-CPU MacBook-Pro-de-Mariano.local x86_64 (Darwin 12.5.0 )
2530MHz
| MacBookPro5,1 2048MB
|
| PROCESS ID: 25860 DATE: 12/27/2013 14:03:29 ART
|
| USER IDS: REAL=mariano (501) EFFECTIVE=mariano (501)
|
+-----------------------------------------------------------------------------+
| GEMSTONE_NRS_ALL =
#dir:$GEMSTONE_DATADIR#log:/$GEMSTONE_LOGDIR/%N%P.log#dir:/opt/gemstone/product/seaside/data
|_____________________________________________________________________________|
_____________________________________________________________________________
| Configuration Files
|
|
|
| System File:
/opt/gemstone/GemStone64Bit3.1.0.4-i386.Darwin/seaside/data/system.conf
|
|
| Executable File:
/opt/gemstone/GemStone64Bit3.1.0.4-i386.Darwin/seaside/data/gem.conf
| Warning: File not found (errno=2,ENOENT, The file or directory specified
cannot
| be found)
|
| using defaults.
|
|_____________________________________________________________________________|
_____________________________________________________________________________
| Gem Configuration Options for process id 25860
|
|_____________________________________________________________________________|
DUMP_OPTIONS = TRUE;
GEM_GCI_LOG_ENABLED = FALSE;
GEM_ABORT_MAX_CRS = 0;
GEM_FREE_FRAME_CACHE_SIZE = -1;
GEM_FREE_FRAME_LIMIT = -1;
GEM_FREE_PAGEIDS_CACHE = 200;
GEM_HALT_ON_ERROR = 0;
GEM_KEEP_MIN_SOFTREFS = 0;
GEM_MAX_SMALLTALK_STACK_DEPTH = 1000;
GEM_NATIVE_CODE_ENABLED = TRUE;
GEM_PRIVATE_PAGE_CACHE_KB = 960;
GEM_PGSVR_COMPRESS_PAGE_TRANSFERS = FALSE;
GEM_PGSVR_FREE_FRAME_CACHE_SIZE = -1;
GEM_PGSVR_FREE_FRAME_LIMIT = -1;
GEM_PGSVR_UPDATE_CACHE_ON_READ = FALSE;
GEM_RPC_KEEPALIVE_INTERVAL = 0;
GEM_RPCGCI_TIMEOUT = 0;
GEM_RPC_USE_SSL = TRUE;
GEM_SOFTREF_CLEANUP_PERCENT_MEM = 50;
GEM_TEMPOBJ_AGGRESSIVE_STUBBING = TRUE;
GEM_TEMPOBJ_CACHE_SIZE = 1800000;
GEM_TEMPOBJ_MESPACE_SIZE = 0;
GEM_TEMPOBJ_OOPMAP_SIZE = 0;
GEM_TEMPOBJ_SCOPES_SIZE = 2000;
GEM_TEMPOBJ_POMGEN_SIZE = 0;
GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE = 90;
GEM_TEMPOBJ_POMGEN_SCAVENGE_INTERVAL = 1800;
GEM_TEMPOBJ_START_ADDR not used on this platform
LOG_WARNINGS = TRUE;
SHR_NUM_FREE_FRAME_SERVERS = -1;
SHR_PAGE_CACHE_LOCKED = FALSE;
SHR_PAGE_CACHE_NUM_PROCS = 10233;
SHR_PAGE_CACHE_NUM_SHARED_COUNTERS = 1900;
SHR_PAGE_CACHE_PERMISSIONS = 660;
SHR_PAGE_CACHE_SIZE_KB = 2000000;
SHR_TARGET_FREE_FRAME_COUNT = -1;
SHR_WELL_KNOWN_PORT_NUMBER = 0;
(vmGc spaceSizes: eden init 2048K max 337536K , survivor init 384K max
56256K,
vmGc old max 1349952K, code max 360000K, perm max 180032K, pom 10 *
150016K = 1500160K,
vmGc remSet 33988K, meSpace max 1720460K oopMapSize 8388608 max
footprint 5548M)
[Info]: libssl-3.1.0.4-64.dylib: loaded
cmdLine=
[Info]: RPC client/gem/minimum GCI levels = 851/851/851
[Info]: Client PID: 6317
native code DISABLED, offset from code memory to libgcilnk.so exceeds 32bits
native code error, emit_call_stub, jmp displacement exceeds 32bits ,
methodId:3589377, ipOffset 56, native code disabled for remainder of session
native code error, emit_call_stub, jmp displacement exceeds 32bits ,
methodId:3589377, ipOffset 96, native code disabled for remainder of session
native code error, emit_call displacement exceeds 32bits ,
methodId:3589377, ipOffset 140, native code disabled for remainder of
session
native code error, emit_call_stub, jmp displacement exceeds 32bits ,
methodId:3589377, ipOffset 144, native code disabled for remainder of
session
native code error, emit_call_stub, jmp displacement exceeds 32bits ,
methodId:3589377, ipOffset 176, native code disabled for remainder of
session
[Info]: User ID: DataCurator
[Info]: Repository: seaside
[Info]: Session ID: 5
[Info]: GCI Client Host: ::ffff:127.0.0.1
[Info]: Page server PID: -1
[Info]: Login Time: 12/27/2013 14:03:29.264 ART
[Info]: libicudata-3.1.0.4-64.dylib: loaded
[Info]: libicuuc-3.1.0.4-64.dylib: loaded
[Info]: libicui18n-3.1.0.4-64.dylib: loaded
GemStone signal handler: signal 11 (SIGSEGV), received from process 0
userId 0
si_code: 0, unknown SI_
Gemstone Signal Handler: Signal 11, SIGSEGV Received
HostFaultHandler: signal = 11
info->si_signo = 11 = 0xb
info->si_code = 0 = 0x0
info->si_errno = 0 = 0x0
info->si_addr = 0x0
signal 11 , received from process 0 userId 0
si_code: 0, unknown SI_
Begin attempt to print C-level stack for current thread of process 25860
at: Fri Dec 27 14:03:46 ART 2013
0 libgcilnk-3.1.0.4-64.dylib 0x000000010135424b
_Z15HostPrintCStackv + 158
1 libgcilnk-3.1.0.4-64.dylib 0x00000001013a34b6 HostFaultHandler
+ 838
2 libsystem_c.dylib 0x00007fff884d890a _sigtramp + 26
3 ??? 0x00007fff5fbf465c 0x0 +
140734799758940
4 libgcilnk-3.1.0.4-64.dylib 0x00000001011df7cd
_Z19IntLpSupControlLoopP2omiPP10omObjSType + 605
5 libgcilnk-3.1.0.4-64.dylib 0x00000001011d6b38
_Z16IntExecuteMethodP13IntStateSTypePP10omObjSTypeS3_i + 376
6 libgcilnk-3.1.0.4-64.dylib 0x00000001010974c2
_ZL14executeFromCtxP2omyyyitiPKyi + 882
7 libgcilnk-3.1.0.4-64.dylib 0x0000000101097d15
_Z23GemDoExecuteFromContextyyyitPy + 149
8 libgcilnk-3.1.0.4-64.dylib 0x000000010104e7ba
_ZL12dispatchLoopP2omP13LgcStateSTypeP13RpcStateSType + 7754
9 libgcilnk-3.1.0.4-64.dylib 0x000000010105087f
_Z12GemDoRpcLoopP2omP13LgcStateSTypeP19IntGciActStateSType + 479
10 libgcilnk-3.1.0.4-64.dylib 0x000000010103a914 _ZL9doConnectv +
516
11 libgcilnk-3.1.0.4-64.dylib 0x000000010103b0e1
_ZL15dispatchCommandv + 817
12 libgcilnk-3.1.0.4-64.dylib 0x000000010103b6e1 _Z4GdbgPKci +
1281
13 libgcilnk-3.1.0.4-64.dylib 0x0000000101051afc gemMain + 2124
14 gem 0x0000000100001bd1 main + 376
15 gem 0x00000001000014b4 start + 52
End of C-level stack for current thread process 25860
_____________________________________________________________________________
| Possible Internal Error: HostCoreDump invoked at 12/27/2013 14:03:47.428
ART
in process 25860
__________________________________
HostCoredump: Waiting 60 seconds for C Debugger to attach, process 25860
--
Mariano
http://marianopeck.wordpress.com
>
>
>
> On Sat, Dec 14, 2013 at 9:40 PM, Dale K. Henrichs <
> dale.henrichs at gemtalksystems.com> wrote:
>
>> Mariano,
>>
>> I'll see what the vms guys have to say about this ...
>>
>> Dale
>> ------------------------------
>>
>> *From: *"Mariano Martinez Peck" <marianopeck at gmail.com>
>> *To: *"John McIntosh" <johnmci at smalltalkconsulting.com>,
>> glass at lists.gemtalksystems.com
>> *Sent: *Thursday, December 12, 2013 10:58:23 AM
>> *Subject: *Re: [Glass] Weird slowdown with a comparison
>>
>>
>>
>>
>>
>> On Thu, Dec 12, 2013 at 9:18 AM, Mariano Martinez Peck <
>> marianopeck at gmail.com> wrote:
>>
>>>
>>>
>>>
>>> On Thu, Dec 12, 2013 at 12:04 AM, John McIntosh <
>>> johnmci at smalltalkconsulting.com> wrote:
>>>
>>>> You restart the stone?
>>>>
>>>>
>>> Yes.
>>>
>>>
>>>> Also
>>>>
>>>> To determine if native code is in use by the currently executing
>>>> session, execute:
>>>>
>>>> GsProcess usingNativeCode
>>>>
>>>>
>>>>
>>> Weird...that gives false!!! yet, GEM_NATIVE_CODE_ENABLED is true...
>>>
>>> mmmm maybe GemTools gem and Topaz gems are started with a false?
>>>
>>> Strange...
>>>
>>>
>> OK.....I found out something. I was running this in my local gemstone
>> (OSX). In the server I have a Linux box and there, GEM_NATIVE_CODE_ENABLED
>> was also true,
>> but GsProcess usingNativeCode also answered true, and indeed, the time
>> to execute that is around 20ms (as I get in Pharo). So that is the
>> explanation of the difference.
>>
>> The admin guide says: "Under some configurations on x86, in particular
>> with Darwin, the 32-bit offset limit my be exceeded in some cases with a
>> very large temporary object cache. If this occurs, native code is disabled."
>> Maybe I am under this situation, I don't know. But my machine is 64
>> bits.
>>
>>
>>
>>
>>
>>>
>>>
>>>>
>>>> On Wed, Dec 11, 2013 at 9:57 PM, Mariano Martinez Peck <
>>>> marianopeck at gmail.com> wrote:
>>>>
>>>>>
>>>>>
>>>>>
>>>>> On Wed, Dec 11, 2013 at 11:42 PM, John McIntosh <
>>>>> johnmci at smalltalkconsulting.com> wrote:
>>>>>
>>>>>> You know I've not played in this area but in data/system.conf
>>>>>>
>>>>>>
>>>>>> # This is set to allow breakpoints to be used ....
>>>>>>
>>>>>> # For production usage, set GEM_NATIVE_CODE_ENABLED
>>>>>>
>>>>>> # in the conf file for the appropriate gem
>>>>>>
>>>>>> # (see
>>>>>>
>>>>>> # $GEMSTONE/seaside/etc/maintenance30.conf
>>>>>>
>>>>>> # $GEMSTONE/seaside/etc/seaside30.conf)
>>>>>>
>>>>>> #
>>>>>>
>>>>>> GEM_NATIVE_CODE_ENABLED = FALSE;
>>>>>>
>>>>>>
>>>>>>
>>>>> Wow...i didn't know the JIT could be enable/disabled. Nice! Thanks for
>>>>> letting me know.
>>>>>
>>>>> I have just check using the Admin -> DoITs -> Gem Configuration Report
>>>>> from GemTools and it was already in TRUE.
>>>>> Just in case, I
>>>>> edited /opt/gemstone/GemStone64Bit3.1.0.4-i386.Darwin/seaside/data/system.conf
>>>>> and add it to TRUE.
>>>>>
>>>>> Still, I am having the same results :(
>>>>>
>>>>> What is weird is that I can use breakpoint in GemStone...so maybe the
>>>>> JIT is not being run even if the boolean appears to be set..
>>>>> But the default says it is TRUE.
>>>>>
>>>>> Thanks,
>>>>>
>>>>>
>>>>>> Admin manual states:
>>>>>>
>>>>>> "By default, generation of native code for Smalltalk methods is
>>>>>> enabled. This is configured using the configuration parameter
>>>>>> GEM_NATIVE_CODE_ENABLED. When native code is disabled, execution is
>>>>>> interpreted; behavior will be identical but somewhat slower. "
>>>>>>
>>>>>> See
>>>>>> http://downloads.gemtalksystems.com/docs/GemStone64/3.1.x/GS64-SysAdminGuide-3.1.pdf page 84
>>>>>>
>>>>>> You could fiddle, restart your stone and run your tests again to see
>>>>>> what happens.
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> On Wed, Dec 11, 2013 at 9:32 PM, Mariano Martinez Peck <
>>>>>> marianopeck at gmail.com> wrote:
>>>>>>
>>>>>>> Hi,
>>>>>>>
>>>>>>> I am profiling some reports that take some time in GemStone and I
>>>>>>> come to a place that I find weird. So I want to check with you to see if
>>>>>>> this is expected.
>>>>>>>
>>>>>>> | char newline carriageReturn |
>>>>>>> char := $a.
>>>>>>> newline := Character lf.
>>>>>>> carriageReturn := Character cr.
>>>>>>> [1 to: 1000000 do: [ :i |
>>>>>>> char == carriageReturn or: [ char == newline ] .
>>>>>>> ]
>>>>>>> ] timeToRun
>>>>>>>
>>>>>>> The following code, takes approx 5 ms in Pharo (Cog). While in
>>>>>>> GemStone it takes me around 60ms. That is 12 times slower...
>>>>>>> Am I doing something wrong? I used #to:do but #timesRepeat got
>>>>>>> similar results. I try to not affect GC by putting the stuff before the
>>>>>>> loop. I tried to run it several times just in case...
>>>>>>>
>>>>>>> So....is that expected or I am missing something?
>>>>>>>
>>>>>>> Thanks,
>>>>>>>
>>>>>>> --
>>>>>>> Mariano
>>>>>>> http://marianopeck.wordpress.com
>>>>>>>
>>>>>>> _______________________________________________
>>>>>>> Glass mailing list
>>>>>>> Glass at lists.gemtalksystems.com
>>>>>>> http://lists.gemtalksystems.com/mailman/listinfo/glass
>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>> --
>>>>>>
>>>>>> ===========================================================================
>>>>>> John M. McIntosh <johnmci at smalltalkconsulting.com>
>>>>>> Corporate Smalltalk Consulting Ltd. Twitter: squeaker68882
>>>>>>
>>>>>> ===========================================================================
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Mariano
>>>>> http://marianopeck.wordpress.com
>>>>>
>>>>
>>>>
>>>>
>>>> --
>>>>
>>>> ===========================================================================
>>>> John M. McIntosh <johnmci at smalltalkconsulting.com>
>>>> Corporate Smalltalk Consulting Ltd. Twitter: squeaker68882
>>>>
>>>> ===========================================================================
>>>>
>>>>
>>>
>>>
>>> --
>>> Mariano
>>> http://marianopeck.wordpress.com
>>>
>>
>>
>>
>> --
>> Mariano
>> http://marianopeck.wordpress.com
>>
>> _______________________________________________
>> Glass mailing list
>> Glass at lists.gemtalksystems.com
>> http://lists.gemtalksystems.com/mailman/listinfo/glass
>>
>>
>>
>
>
> --
> Mariano
> http://marianopeck.wordpress.com
>
--
Mariano
http://marianopeck.wordpress.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gemtalksystems.com/mailman/private/glass/attachments/20131227/bf64f1c0/attachment-0001.html>
More information about the Glass
mailing list