Bug 494753

Summary: Large spew of 'freeing invalid memtype' messages starting openoffice writer....
Product: [Fedora] Fedora Reporter: Tom London <selinux>
Component: kernelAssignee: Kristian Høgsberg <krh>
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: rawhideCC: amit.shah, atontti+rh, florin, james, kernel-maint, kevin, mishu, quintela, roysjosh
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-04-23 21:36:05 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
Complete output of dmesg after large spew of messages
none
Screenshot of "gnome-display-preferences" none

Description Tom London 2009-04-08 00:38:11 UTC
Description of problem:
Not sure what happened, but when I clicked on a '.doc' link in firefox, and then selected "open in openoffice writer", the system appeared to hang for about 20-30 seconds (music on rhythmbox stopped, cursor froze, ...), and then when it thawed, I saw about 2100 messages in /var/log/messages like:

Apr  7 17:26:46 tlondon kernel: Xorg:2929 freeing invalid memtype d34ec000-d34ed000
Apr  7 17:26:46 tlondon kernel: Xorg:2929 freeing invalid memtype d34ed000-d34ee000
Apr  7 17:26:46 tlondon kernel: Xorg:2929 freeing invalid memtype d34ee000-d34ef000
Apr  7 17:26:46 tlondon kernel: Xorg:2929 freeing invalid memtype d34ef000-d34f0000
Apr  7 17:26:46 tlondon kernel: Xorg:2929 freeing invalid memtype d34f0000-d34f1000
Apr  7 17:26:46 tlondon kernel: Xorg:2929 freeing invalid memtype d34f1000-d34f2000
Apr  7 17:26:46 tlondon kernel: Xorg:2929 freeing invalid memtype d34f2000-d34f3000

Counting them:
[tbl@tlondon ~]$ dmesg | grep 'freeing invalid memtype' | wc
   2172   10860  112944
[tbl@tlondon ~]$ 

System is Thinkpad X200, Intel graphics, ....

Here is the start of the spew in /var/log/messages:
Apr  7 17:19:52 tlondon NetworkManager: <info>  (wlan1): supplicant connection state:  completed -> group handshake
Apr  7 17:19:52 tlondon NetworkManager: <info>  (wlan1): supplicant connection state:  group handshake -> completed
Apr  7 17:26:04 tlondon pulseaudio[3276]: alsa-sink.c: Increasing minimal latency to 126.00 ms
Apr  7 17:26:05 tlondon pulseaudio[3276]: alsa-sink.c: Increasing wakeup watermark to 115.99 ms
Apr  7 17:26:12 tlondon pulseaudio[3276]: alsa-sink.c: Increasing minimal latency to 136.00 ms
Apr  7 17:26:13 tlondon pulseaudio[3276]: alsa-sink.c: Increasing wakeup watermark to 125.99 ms
Apr  7 17:26:13 tlondon pulseaudio[3276]: alsa-sink.c: Increasing minimal latency to 146.00 ms
Apr  7 17:26:14 tlondon pulseaudio[3276]: alsa-sink.c: Increasing wakeup watermark to 135.99 ms
Apr  7 17:26:15 tlondon pulseaudio[3276]: alsa-sink.c: Increasing minimal latency to 156.00 ms
Apr  7 17:26:15 tlondon pulseaudio[3276]: alsa-sink.c: Increasing wakeup watermark to 145.99 ms
Apr  7 17:26:44 tlondon kernel: Xorg:2929 freeing invalid memtype df1d1000-df1d2000
Apr  7 17:26:44 tlondon kernel: Xorg:2929 freeing invalid memtype df1d2000-df1d3000
Apr  7 17:26:44 tlondon kernel: Xorg:2929 freeing invalid memtype df1d3000-df1d4000
Apr  7 17:26:44 tlondon kernel: Xorg:2929 freeing invalid memtype df1d4000-df1d5000
Apr  7 17:26:44 tlondon kernel: Xorg:2929 freeing invalid memtype df1d5000-df1d6000



Version-Release number of selected component (if applicable):
kernel-2.6.29.1-54.fc11.x86_64
xorg-x11-server-common-1.6.0-17.fc11.x86_64
xorg-x11-server-Xorg-1.6.0-17.fc11.x86_64


How reproducible:
Don't know....

Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:

Comment 1 Tom London 2009-04-08 00:40:08 UTC
Created attachment 338637 [details]
Complete output of dmesg after large spew of messages

Attaching complete dmesg output showing spew....

Comment 2 Chuck Ebbert 2009-04-08 14:08:25 UTC
Huh... supposedly the fix for this went into 2.6.29.1:
http://lkml.indiana.edu/hypermail/linux/kernel/0903.2/03461.html

Comment 3 Tom London 2009-04-08 16:04:32 UTC
Created attachment 338746 [details]
Screenshot of "gnome-display-preferences"

A bit more (possibly unrelated) info on this.....

This happened when I was running Thinkpad X200 with xorg-x11-drv-intel-2.6.99.902-2.fc11.x86_64 with KMS enabled (that is, I did NOT boot with "nomodeset nopat") and with an external monitor (HP).

In that setup, sometime prior to the above spew, I ran "gnome-display-properties", and it showed 3 screens (not 2!): HP external monitor, Lenovo laptop screen, and "unknown".

This does not happen if I boot with "nomodeset nopat".

Could this be related somehow?

Running 'xrandr'... Does this show 3 "pipes" active (VGA1, LVDS1, DVI1)?

[tbl@tlondon bin]$ xrandr
Screen 0: minimum 320 x 200, current 1280 x 1024, maximum 8192 x 8192
VGA1 connected 1280x1024+0+0 (normal left inverted right x axis y axis) 376mm x 301mm
   1280x1024      60.0*+   75.0  
   1152x864       75.0  
   1024x768       75.1     70.1     60.0  
   832x624        74.6  
   800x600        72.2     75.0     60.3  
   640x480        72.8     75.0     60.0  
   720x400        70.1  
LVDS1 connected 1280x800+0+0 (normal left inverted right x axis y axis) 261mm x 163mm
   1280x800       60.0*+   50.0  
DVI1 connected (normal left inverted right x axis y axis)
   1024x768       60.0  
   800x600        60.3  
   640x480        59.9  
DVI2 disconnected (normal left inverted right x axis y axis)
[tbl@tlondon bin]$

Comment 4 Tom London 2009-04-08 16:14:08 UTC
Hmmm... after running gnome-display-properties to get the screenshow above, looks like I got 768 'freeing invalid memtype' messages ....


Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4163000-d4164000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4164000-d4165000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4165000-d4166000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4166000-d4167000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4167000-d4168000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4168000-d4169000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4169000-d416a000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d416a000-d416b000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d416b000-d416c000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d416c000-d416d000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d416d000-d416e000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d416e000-d416f000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d416f000-d4170000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4170000-d4171000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4171000-d4172000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4172000-d4173000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4173000-d4174000
Apr  8 09:06:39 tlondon kernel: Xorg:2914 freeing invalid memtype d4174000-d4175000
<<<<<SNIP>>>>>

Comment 5 James 2009-04-08 18:07:49 UTC
I've just seen a load of these:

Xorg:7427 freeing invalid memtype d47be000-d47bf000
Xorg:7427 freeing invalid memtype d47bf000-d47c0000
Xorg:7427 freeing invalid memtype d47c0000-d47c1000
Xorg:7427 freeing invalid memtype d47c1000-d47c2000
...
Xorg:7427 freeing invalid memtype d401a000-d401b000
Xorg:7427 freeing invalid memtype d401b000-d401c000
Xorg:7427 freeing invalid memtype d401c000-d401d000
Xorg:7427 freeing invalid memtype d401d000-d401e000

etc. Happened when viewing a large (2048x1356) image in Firefox. Intel X3100 graphics.

kernel-2.6.29.1-54.fc11.x86_64
xorg-x11-drv-intel-2.6.99.902-2.fc11.x86_64

(Another bunch just showed up while I was doing nothing special, managed to put quite a bit of latency into the system, though.)

Comment 6 James 2009-04-08 19:09:11 UTC
...which was just followed by another glut of "freeing invalid memtype" messages and:

[drm:i915_gem_object_bind_to_gtt] *ERROR* GTT full, but LRU list empty
[drm:i915_gem_object_pin] *ERROR* Failure to bind: -12
[drm:i915_gem_evict_something] *ERROR* inactive empty 1 request empty 1 flushing empty 1

Comment 7 Tom London 2009-04-09 17:06:23 UTC
I don't see the "GTT full", etc. messages of #6, but I did get the "freeing invalid memtype" for a process other than Xorg, extreme tuxracer....:

Apr  8 15:56:45 tlondon pulseaudio[3302]: alsa-sink.c: Increasing minimal latency to 26.00 ms
Apr  8 15:56:48 tlondon pulseaudio[3302]: alsa-sink.c: Increasing minimal latency to 36.00 ms
Apr  8 15:56:48 tlondon kernel: etracer:20290 freeing invalid memtype ddb6b000-ddb6c000
Apr  8 15:56:48 tlondon kernel: etracer:20290 freeing invalid memtype ddb6c000-ddb6d000
Apr  8 15:56:48 tlondon kernel: etracer:20290 freeing invalid memtype ddb6d000-ddb6e000
Apr  8 15:56:48 tlondon kernel: etracer:20290 freeing invalid memtype ddb6e000-ddb6f000
Apr  8 15:56:48 tlondon kernel: etracer:20290 freeing invalid memtype ddb6f000-ddb70000
Apr  8 15:56:48 tlondon kernel: etracer:20290 freeing invalid memtype ddb70000-ddb71000
<<<<<SNIP>>>>>

Looks like I got over 20,000 of them from a single run of etracer....

[root@tlondon ~]# grep etracer /var/log/messages | wc
  20221  202210 1779448
[root@tlondon ~]# 

BTW, the last of these occurred 10 seconds later:

[root@tlondon ~]# grep etracer /var/log/messages | tail
Apr  8 15:56:58 tlondon kernel: etracer:20290 freeing invalid memtype d7cc5000-d7cc6000
Apr  8 15:56:58 tlondon kernel: etracer:20290 freeing invalid memtype d7cc6000-d7cc7000
Apr  8 15:56:58 tlondon kernel: etracer:20290 freeing invalid memtype d7cc7000-d7cc8000
Apr  8 15:56:58 tlondon kernel: etracer:20290 freeing invalid memtype d7cc8000-d7cc9000
Apr  8 15:56:58 tlondon kernel: etracer:20290 freeing invalid memtype d7cc9000-d7cca000
Apr  8 15:56:58 tlondon kernel: etracer:20290 freeing invalid memtype d7cca000-d7ccb000
Apr  8 15:56:58 tlondon kernel: etracer:20290 freeing invalid memtype d7ccb000-d7ccc000
Apr  8 15:56:58 tlondon kernel: etracer:20290 freeing invalid memtype d7ccc000-d7ccd000
Apr  8 15:56:58 tlondon kernel: etracer:20290 freeing invalid memtype d7ccd000-d7cce000
Apr  8 15:56:58 tlondon kernel: etracer:20290 freeing invalid memtype d7cce000-d7ccf000
[root@tlondon ~]#

Comment 8 Tom London 2009-04-09 17:35:29 UTC
Also, here is output from 'xrandr' when my Thinkpad X200 is booted with 'nomodeset nopat':  (also connected to older monitor)

[tbl@tlondon ~]$ xrandr
Screen 0: minimum 320 x 200, current 1280 x 1024, maximum 1280 x 1280
VGA connected 1280x1024+0+0 (normal left inverted right x axis y axis) 359mm x 287mm
   1280x1024      75.0*    60.0  
   1152x864       75.0  
   1024x768       75.0     70.1     60.0  
   832x624        74.6  
   800x600        72.2     75.0     60.3     56.2  
   640x480        75.0     72.8     66.7     59.9  
LVDS connected (normal left inverted right x axis y axis)
   1280x800       60.0 +   50.0  
   1024x768       85.0     75.0     70.1     60.0  
   832x624        74.6  
   800x600        85.1     72.2     75.0     60.3     56.2  
   640x480        85.0     72.8     75.0     59.9  
   720x400        85.0  
   640x400        85.1  
   640x350        85.1  
HDMI-1 disconnected (normal left inverted right x axis y axis)
HDMI-2 disconnected (normal left inverted right x axis y axis)
[tbl@tlondon ~]$

Comment 9 Florin Iucha 2009-04-11 07:01:57 UTC
I got the "Xorg:3752 freeing invalid memtype" in my kernel log as well.  I have a Thinkpad T60 with integrated Intel graphics and displaying on an external Dell LCD.

Comment 10 James 2009-04-13 21:05:39 UTC
I booted with nopat today, I've not seen any f-i-m messages or the associated freezes. I'm not sure if this has had an effect on performance...

Comment 11 Kevin Fenzi 2009-04-17 15:40:13 UTC
I see this here as well...

ohm(kevin)[~] uname -r
2.6.29.1-70.fc11.x86_64
ohm(kevin)[~] lspci | grep -i display
00:02.1 Display controller: Intel Corporation Mobile 945GM/GMS/GME, 943/940GML Express Integrated Graphics Controller (rev 03)
ohm(kevin)[~] dmesg | grep invalid | wc -l                                             9:39:17
2518

Comment 12 Kevin Fenzi 2009-04-17 15:41:53 UTC
*** Bug 496029 has been marked as a duplicate of this bug. ***

Comment 13 Chuck Ebbert 2009-04-18 02:17:13 UTC
Looks like allocating the memory in one big chunk and then freeing it piecemeal could cause that message:

        err = -EINVAL;
        ...
        spin_lock(&memtype_lock);
        list_for_each_entry(entry, &memtype_list, nd) {
                if (entry->start == start && entry->end == end) {
                        if (cached_entry == entry || cached_start == start)
                                cached_entry = NULL;

                        list_del(&entry->nd);
                        kfree(entry);
                        err = 0;
                        break;
                }
        }
        spin_unlock(&memtype_lock);

        if (err) {
                printk(KERN_INFO "%s:%d freeing invalid memtype %Lx-%Lx\n",
                        current->comm, current->pid, start, end);
        }

Comment 14 Tom London 2009-04-20 20:03:51 UTC
I've been stressing kernel-2.6.29.1-101.fc11.x86_64 all morning, and have not been able to reproduce the spew.....

Comment 15 Tom London 2009-04-23 21:36:05 UTC
Believe this is fixed.  Thanks!

Closing......